From e2d8bfe5cfa8ed014fbce21b924d362ffc87512a Mon Sep 17 00:00:00 2001 From: Hao Kung Date: Wed, 10 Jun 2015 15:13:28 -0700 Subject: [PATCH] Cleanup logging in SignInManager --- .../SignInManager.cs | 139 ++++++++---------- .../SignInManagerTest.cs | 66 ++------- 2 files changed, 77 insertions(+), 128 deletions(-) diff --git a/src/Microsoft.AspNet.Identity/SignInManager.cs b/src/Microsoft.AspNet.Identity/SignInManager.cs index 39c154a05b..7206d8b28b 100644 --- a/src/Microsoft.AspNet.Identity/SignInManager.cs +++ b/src/Microsoft.AspNet.Identity/SignInManager.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using System.Linq; -using System.Runtime.CompilerServices; using System.Security.Claims; using System.Threading.Tasks; using Microsoft.AspNet.Hosting; @@ -90,14 +89,16 @@ namespace Microsoft.AspNet.Identity { if (Options.SignIn.RequireConfirmedEmail && !(await UserManager.IsEmailConfirmedAsync(user))) { - return Logger.Log(false); + Logger.LogWarning("User {userId} cannot sign in without a confirmed email.", await UserManager.GetUserIdAsync(user)); + return false; } if (Options.SignIn.RequireConfirmedPhoneNumber && !(await UserManager.IsPhoneNumberConfirmedAsync(user))) { - return Logger.Log(false); + Logger.LogWarning("User {userId} cannot sign in without a confirmed phone number.", await UserManager.GetUserIdAsync(user)); + return false; } - return Logger.Log(true); + return true; } /// @@ -197,34 +198,32 @@ namespace Microsoft.AspNet.Identity throw new ArgumentNullException(nameof(user)); } - using (await BeginLoggingScopeAsync(user)) + var error = await PreSignInCheck(user); + if (error != null) { - var error = await PreSignInCheck(user); - if (error != null) - { - return Logger.Log(error); - } - if (await IsLockedOut(user)) - { - return Logger.Log(SignInResult.LockedOut); - } - if (await UserManager.CheckPasswordAsync(user, password)) - { - await ResetLockout(user); - return Logger.Log(await SignInOrTwoFactorAsync(user, isPersistent)); - } - if (UserManager.SupportsUserLockout && shouldLockout) - { - // If lockout is requested, increment access failed count which might lock out the user - await UserManager.AccessFailedAsync(user); - if (await UserManager.IsLockedOutAsync(user)) - { - - return Logger.Log(SignInResult.LockedOut); - } - } - return Logger.Log(SignInResult.Failed); + return error; } + if (await IsLockedOut(user)) + { + return await LockedOut(user); + } + if (await UserManager.CheckPasswordAsync(user, password)) + { + await ResetLockout(user); + return await SignInOrTwoFactorAsync(user, isPersistent); + } + Logger.LogWarning("User {userId} failed to provide the correct password.", await UserManager.GetUserIdAsync(user)); + + if (UserManager.SupportsUserLockout && shouldLockout) + { + // If lockout is requested, increment access failed count which might lock out the user + await UserManager.AccessFailedAsync(user); + if (await UserManager.IsLockedOutAsync(user)) + { + return await LockedOut(user); + } + } + return SignInResult.Failed; } /// @@ -315,34 +314,31 @@ namespace Microsoft.AspNet.Identity return SignInResult.Failed; } - using (await BeginLoggingScopeAsync(user)) + var error = await PreSignInCheck(user); + if (error != null) { - var error = await PreSignInCheck(user); - if (error != null) - { - return Logger.Log(error); - } - if (await UserManager.VerifyTwoFactorTokenAsync(user, provider, code)) - { - // When token is verified correctly, clear the access failed count used for lockout - await ResetLockout(user); - // Cleanup external cookie - if (twoFactorInfo.LoginProvider != null) - { - Context.Authentication.SignOut(IdentityOptions.ExternalCookieAuthenticationScheme); - } - if (rememberClient) - { - await RememberTwoFactorClientAsync(user); - } - await UserManager.ResetAccessFailedCountAsync(user); - await SignInAsync(user, isPersistent, twoFactorInfo.LoginProvider); - return Logger.Log(SignInResult.Success); - } - // If the token is incorrect, record the failure which also may cause the user to be locked out - await UserManager.AccessFailedAsync(user); - return Logger.Log(SignInResult.Failed); + return error; } + if (await UserManager.VerifyTwoFactorTokenAsync(user, provider, code)) + { + // When token is verified correctly, clear the access failed count used for lockout + await ResetLockout(user); + // Cleanup external cookie + if (twoFactorInfo.LoginProvider != null) + { + Context.Authentication.SignOut(IdentityOptions.ExternalCookieAuthenticationScheme); + } + if (rememberClient) + { + await RememberTwoFactorClientAsync(user); + } + await UserManager.ResetAccessFailedCountAsync(user); + await SignInAsync(user, isPersistent, twoFactorInfo.LoginProvider); + return SignInResult.Success; + } + // If the token is incorrect, record the failure which also may cause the user to be locked out + await UserManager.AccessFailedAsync(user); + return SignInResult.Failed; } /// @@ -377,15 +373,12 @@ namespace Microsoft.AspNet.Identity return SignInResult.Failed; } - using (await BeginLoggingScopeAsync(user)) + var error = await PreSignInCheck(user); + if (error != null) { - var error = await PreSignInCheck(user); - if (error != null) - { - return Logger.Log(error); - } - return Logger.Log(await SignInOrTwoFactorAsync(user, isPersistent, loginProvider)); + return error; } + return await SignInOrTwoFactorAsync(user, isPersistent, loginProvider); } /// @@ -451,18 +444,6 @@ namespace Microsoft.AspNet.Identity return properties; } - /// - /// Starts a scope for wrapping log messages, as an asynchronous operation. - /// - /// The current user. - /// The method that called this method. - /// The task object representing the asynchronous operation. - protected virtual async Task BeginLoggingScopeAsync(TUser user, [CallerMemberName] string methodName = null) - { - var state = Resources.FormatLoggingResultMessageForUser(methodName, await UserManager.GetUserIdAsync(user)); - return Logger?.BeginScope(state); - } - /// /// Creates a claims principal for the specified 2fa information. /// @@ -538,6 +519,12 @@ namespace Microsoft.AspNet.Identity return UserManager.SupportsUserLockout && await UserManager.IsLockedOutAsync(user); } + private async Task LockedOut(TUser user) + { + Logger.LogWarning("User {userId} is currently locked out.", await UserManager.GetUserIdAsync(user)); + return SignInResult.LockedOut; + } + private async Task PreSignInCheck(TUser user) { if (!await CanSignInAsync(user)) @@ -546,7 +533,7 @@ namespace Microsoft.AspNet.Identity } if (await IsLockedOut(user)) { - return SignInResult.LockedOut; + return await LockedOut(user); } return null; } diff --git a/test/Microsoft.AspNet.Identity.Test/SignInManagerTest.cs b/test/Microsoft.AspNet.Identity.Test/SignInManagerTest.cs index 355b8978b6..3e19df4edd 100644 --- a/test/Microsoft.AspNet.Identity.Test/SignInManagerTest.cs +++ b/test/Microsoft.AspNet.Identity.Test/SignInManagerTest.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Linq; using System.Security.Claims; using System.Text; @@ -77,7 +78,6 @@ namespace Microsoft.AspNet.Identity.Test Assert.Throws("claimsFactory", () => new SignInManager(userManager, contextAccessor.Object, null, null, null)); } - //TODO: Mock fails in K (this works fine in net45) //[Fact] //public async Task EnsureClaimsPrincipalFactoryCreateIdentityCalled() //{ @@ -86,9 +86,8 @@ namespace Microsoft.AspNet.Identity.Test // var userManager = MockHelpers.TestUserManager(); // var identityFactory = new Mock>(); // const string authType = "Test"; - // var testIdentity = new ClaimsIdentity(authType); - // identityFactory.Setup(s => s.CreateAsync(userManager, user, authType)).ReturnsAsync(testIdentity).Verifiable(); - // userManager.UserClaimsPrincipalFactory = identityFactory.Object; + // var testIdentity = new ClaimsPrincipal(); + // identityFactory.Setup(s => s.CreateAsync(user)).ReturnsAsync(testIdentity).Verifiable(); // var context = new Mock(); // var response = new Mock(); // context.Setup(c => c.Response).Returns(response.Object).Verifiable(); @@ -126,10 +125,7 @@ namespace Microsoft.AspNet.Identity.Test var claimsFactory = new UserClaimsPrincipalFactory(manager.Object, roleManager.Object, options.Object); var logStore = new StringBuilder(); var logger = MockHelpers.MockILogger>(logStore); - var helper = new SignInManager(manager.Object, contextAccessor.Object, claimsFactory, options.Object, null); - helper.Logger = logger.Object; - var expectedScope = string.Format("{0} for {1}: {2}", "PasswordSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "PasswordSignInAsync", "Lockedout"); + var helper = new SignInManager(manager.Object, contextAccessor.Object, claimsFactory, options.Object, logger.Object); // Act var result = await helper.PasswordSignInAsync(user.UserName, "bogus", false, false); @@ -137,8 +133,7 @@ namespace Microsoft.AspNet.Identity.Test // Assert Assert.False(result.Succeeded); Assert.True(result.IsLockedOut); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); + Assert.True(logStore.ToString().Contains($"User {user.Id} is currently locked out.")); manager.Verify(); } @@ -162,10 +157,7 @@ namespace Microsoft.AspNet.Identity.Test options.Setup(a => a.Options).Returns(identityOptions); var claimsFactory = new UserClaimsPrincipalFactory(manager, roleManager.Object, options.Object); var sm = new SignInManager(manager, contextAccessor.Object, claimsFactory, options.Object, null); - if (logStore != null) - { - sm.Logger = MockHelpers.MockILogger>(logStore).Object; - } + sm.Logger = MockHelpers.MockILogger>(logStore ?? new StringBuilder()).Object; return sm; } @@ -185,18 +177,13 @@ namespace Microsoft.AspNet.Identity.Test var auth = new Mock(); context.Setup(c => c.Authentication).Returns(auth.Object).Verifiable(); SetupSignIn(auth, user.Id, isPersistent); - var logStore = new StringBuilder(); - var helper = SetupSignInManager(manager.Object, context.Object, logStore); - var expectedScope = string.Format("{0} for {1}: {2}", "PasswordSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "PasswordSignInAsync", "Succeeded"); + var helper = SetupSignInManager(manager.Object, context.Object); // Act var result = await helper.PasswordSignInAsync(user.UserName, "password", isPersistent, false); // Assert Assert.True(result.Succeeded); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); manager.Verify(); context.Verify(); auth.Verify(); @@ -285,10 +272,7 @@ namespace Microsoft.AspNet.Identity.Test It.Is(id => id.FindFirstValue(ClaimTypes.Name) == user.Id), It.IsAny())).Verifiable(); context.Setup(c => c.Authentication).Returns(auth.Object).Verifiable(); - var logStore = new StringBuilder(); - var helper = SetupSignInManager(manager.Object, context.Object, logStore); - var expectedScope = string.Format("{0} for {1}: {2}", "PasswordSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "PasswordSignInAsync", "RequiresTwoFactor"); + var helper = SetupSignInManager(manager.Object, context.Object); // Act var result = await helper.PasswordSignInAsync(user.UserName, "password", false, false); @@ -296,8 +280,6 @@ namespace Microsoft.AspNet.Identity.Test // Assert Assert.False(result.Succeeded); Assert.True(result.RequiresTwoFactor); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); manager.Verify(); context.Verify(); auth.Verify(); @@ -326,18 +308,13 @@ namespace Microsoft.AspNet.Identity.Test var auth = new Mock(); context.Setup(c => c.Authentication).Returns(auth.Object).Verifiable(); SetupSignIn(auth, user.Id, isPersistent, loginProvider); - var logStore = new StringBuilder(); - var helper = SetupSignInManager(manager.Object, context.Object, logStore); - var expectedScope = string.Format("{0} for {1}: {2}", "ExternalLoginSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "ExternalLoginSignInAsync", "Succeeded"); + var helper = SetupSignInManager(manager.Object, context.Object); // Act var result = await helper.ExternalLoginSignInAsync(loginProvider, providerKey, isPersistent); // Assert Assert.True(result.Succeeded); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); manager.Verify(); context.Verify(); auth.Verify(); @@ -442,18 +419,13 @@ namespace Microsoft.AspNet.Identity.Test } auth.Setup(a => a.AuthenticateAsync(IdentityOptions.TwoFactorUserIdCookieAuthenticationScheme)).ReturnsAsync(authResult).Verifiable(); context.Setup(c => c.Authentication).Returns(auth.Object).Verifiable(); - var logStore = new StringBuilder(); - var helper = SetupSignInManager(manager.Object, context.Object, logStore); - var expectedScope = string.Format("{0} for {1}: {2}", "TwoFactorSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "TwoFactorSignInAsync", "Succeeded"); + var helper = SetupSignInManager(manager.Object, context.Object); // Act var result = await helper.TwoFactorSignInAsync(provider, code, isPersistent, rememberClient); // Assert Assert.True(result.Succeeded); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); manager.Verify(); context.Verify(); auth.Verify(); @@ -535,8 +507,7 @@ namespace Microsoft.AspNet.Identity.Test auth.Setup(a => a.SignOut(IdentityOptions.TwoFactorUserIdCookieAuthenticationScheme)).Verifiable(); auth.Setup(a => a.SignOut(IdentityOptions.ExternalCookieAuthenticationScheme)).Verifiable(); IdentityOptions.ApplicationCookieAuthenticationScheme = authenticationScheme; - var logStore = new StringBuilder(); - var helper = SetupSignInManager(manager.Object, context.Object, logStore); + var helper = SetupSignInManager(manager.Object, context.Object); // Act helper.SignOut(); @@ -558,15 +529,12 @@ namespace Microsoft.AspNet.Identity.Test var context = new Mock(); var logStore = new StringBuilder(); var helper = SetupSignInManager(manager.Object, context.Object, logStore); - var expectedScope = string.Format("{0} for {1}: {2}", "PasswordSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "PasswordSignInAsync", "Failed"); // Act var result = await helper.PasswordSignInAsync(user.UserName, "bogus", false, false); // Assert Assert.False(result.Succeeded); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); + Assert.True(logStore.ToString().Contains($"User {user.Id} failed to provide the correct password.")); manager.Verify(); context.Verify(); } @@ -641,8 +609,6 @@ namespace Microsoft.AspNet.Identity.Test identityOptions.SignIn.RequireConfirmedEmail = true; var logStore = new StringBuilder(); var helper = SetupSignInManager(manager.Object, context.Object, logStore, identityOptions); - var expectedScope = string.Format("{0} for {1}: {2}", "PasswordSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "CanSignInAsync", confirmed.ToString()); // Act var result = await helper.PasswordSignInAsync(user, "password", false, false); @@ -651,8 +617,7 @@ namespace Microsoft.AspNet.Identity.Test Assert.Equal(confirmed, result.Succeeded); Assert.NotEqual(confirmed, result.IsNotAllowed); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); + Assert.Equal(confirmed, !logStore.ToString().Contains($"User {user.Id} cannot sign in without a confirmed email.")); manager.Verify(); context.Verify(); @@ -690,8 +655,6 @@ namespace Microsoft.AspNet.Identity.Test identityOptions.SignIn.RequireConfirmedPhoneNumber = true; var logStore = new StringBuilder(); var helper = SetupSignInManager(manager.Object, context.Object, logStore, identityOptions); - var expectedScope = string.Format("{0} for {1}: {2}", "PasswordSignInAsync", "user", user.Id); - var expectedLog = string.Format("{0} : {1}", "CanSignInAsync", confirmed.ToString()); // Act var result = await helper.PasswordSignInAsync(user, "password", false, false); @@ -699,8 +662,7 @@ namespace Microsoft.AspNet.Identity.Test // Assert Assert.Equal(confirmed, result.Succeeded); Assert.NotEqual(confirmed, result.IsNotAllowed); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedLog)); - Assert.NotEqual(-1, logStore.ToString().IndexOf(expectedScope)); + Assert.Equal(confirmed, !logStore.ToString().Contains($"User {user.Id} cannot sign in without a confirmed phone number.")); manager.Verify(); context.Verify(); auth.Verify();