Random token invalid issue.

Issue

I have been getting a random issue with users trying to reset their passwords in our production and test environments.

The main problem is that we recently moved about 10k users from a legacy login system over to the identity server. When we did this their login page changed so everyone who had their password saved in their browser and now cant remember it has had to reset their password. A small percentage of those users has not been able to reset their password. They always get an invalid token error. (Support says some of the email verification tokens for new users is also invalid but i have not seen this personally I need to have them send me these as well for debugging.)

I have not been able to recreate this on my local machine. I tried copying their concurrencyStamp and secrutystamp to my own account hoping that would force it to generate an invalid token. That did not work either. I have about 700 test users on my local machine i went though about 50 of them before i started to loose my mind and gave up trying to recreate it that way.

The error in question is

VerifyUserTokenAsync() failed with purpose: ResetPassword for user 289512042.

This didnt give me much information so i added my own debuging and added this issue request which i will be posting a pull request for later this morning Show errors in the log from VerifyUserTokenAsync

User reset password failed [user.Id: 289512042] Invalid code

So i know that the error is that the code is not valid.

I can verify that the code is not to old. I have seen the the logs the user requesting it and then getting the email and clicking on the link within minutes. It does not work.
I also have a supporter who swears she watched the user do it over team viewer they event tried using an incognito window.

About the application

.net core 2.0
Identity server 4.
Entity framework with Asp .net users.
one Redis server running in test and production.
Production and test running in a docker swarm.
Identity server # of instances Test running two instances production running one. We are still trying to fix bug with this user move so didnt want to make matters worse by running multiple instances in production yet. I had it running two instances last week for a day or so just to test it.

Start up

_logger.LogInformation(LoggingEvents.StartupRedis,
$"Data protection enabled with with redis: {Configuration["Redis:ApplicationName"]}", Configuration["Redis:ApplicationName"]);

services.ConfigureApplicationCookie(opts =>
                    opts.SessionStore = new RedisCacheTicketStore(new RedisCacheOptions()
                    {
                        Configuration = Configuration["Redis:HostPort"]
                    }, _logger, Configuration)
                );
 var redis = ConnectionMultiplexer.Connect(Configuration["Redis:HostPort"]);
services.AddDataProtection(config => config.ApplicationDiscriminator = Configuration["Redis:ApplicationName"])
                    .SetApplicationName(Configuration["Redis:ApplicationName"])
                    .PersistKeysToRedis(redis, "DataProtection-Keys");

Application name is based upon environment "ApplicationName": "XXXXIdentityserver-v2-Production-Key"

We currently only have one redis server which is serving both production and test.

Background Info

This identity server has been running for around two years. I recently added asp.net users and imported about 10k users into it from a legacy system, so that it now manages the users. When i did the import of the users I neglected to create them a concurrencyStamp and securitystamp. This lead to an issue where legacy users were creating a reset password token that would never validate. (It may be an idea to test that the stamps are not null before creating the token in the library itself. ) I have added a check in my code before creating the token to ensure that a user has the tokens before creating the reset password token.

if (user.SecurityStamp == null) await _userManager.UpdateSecurityStampAsync(user);

This random invalid token is happening on new users as well as legacy users who have already reset their password once. So it is IMO unrelated to the fact that these are legacy users as opposed to newly created users.

Reset password

[HttpPost]
[AllowAnonymous]
[ValidateAntiForgeryToken]
public async Task<IActionResult> ForgotPassword([FromForm] ForgotPasswordViewModel model)
{

     {removed}

      var passwordResetCode = await _userManager.GeneratePasswordResetTokenAsync(user);
      var passwordResetCallbackUrl = Url.ResetPasswordCallbackLink(user, model.ReturnUrl, passwordResetCode, Request.Scheme);

       {removed}
       return RedirectToAction(nameof(ForgotPasswordConfirmation));
}

Helper method

public static string ResetPasswordCallbackLink(this IUrlHelper urlHelper, ApplicationUser user , string returnUrl, string code, string scheme)
        {
            return urlHelper.Action(
                action: nameof(AccountController.ResetPassword),
                controller: "Account",
                values: new { userid = user.Id, code = Uri.EscapeDataString(code), returnUrl },
                protocol: scheme);
        }

EscapeDataString

I have recently started using EscapeDataString i read this very old question on stackAsp.NET Identity 2 giving “Invalid Token” error and figured it was worth a try. I cant verify that it works yet. Its fall vacation this year the number of users trying to reset their password this week isnt enough to verify that its working.

An Example

If it helps this was an invalid code that had been requested last week. At the time of its use it was only just created.

https://logintest.XXXXX.biz/Account/ResetPassword?userid=25296662&code=CfDJ8PJUKz96qKpBrYBBC57a4f3D%2Bgt7xJOmrQN9kMSVuLUXecxJMDVFsG%2BFd5T7BJZai84psokeVyTD5JUJRzzNlFmd%2F%2BISYRh%2Bm%2FxbLrqS4oY0FBfYNy1GcZx%2BlRawi1bXAzlyksAiITrLOUYEaz%2F5J53CLmjGUhG3JlTxK9J6PiXH

Note

I hate to bother you with an issue that I cant prove, cant recreate, and cant debug. But i am running out of ideas. I sent out a call on Twitter and Barry Dorrans responded and suggested i post this here. Any help would be greatly appreciated.

Our UserId is a long not the standard GUID. This was due to the legacy system. Changing that to support GUID would have been to big of a job.

My current idea

Ok after digging around in the library. I think I have an idea. What if i create a custom IUserTwoFactorTokenProvider basically copy DataProtectorTokenProvider. My idea is to create a validation method then call that from ValidateAsync. I want to use the exact same one thats used in DataProtectorTokenProvider. By having one that i can call that will return the error rather than just a true and false i can call that if the validate fails and then log why it failed.

@LindaLawton do these users have valid security stamps?

Yes the users in question have what appears to be valid stamps. I didn't create the stamps them they were created by the system. Do you have a way for me to test if they are valid?

You should be able to test users by just calling Generate and Validate right away, see if any of the users fail when doing that...

   var token = await _userManager.GeneratePasswordResetTokenAsync(user);
   var result = await VerifyUserTokenAsync(user, _userManger.Options.Tokens.PasswordResetTokenProvider, _userManager.ResetPasswordTokenPurpose, token))

Otherwise if i were to guess what's going on, maybe the security stamp for those users has changed after the token was generated, that would cause the tokens to be invalid.

@blowdart there aren't any known issues with data protection like this are there? Since there always could be some issue with dataprotection causing this as well

generation of the token never fails. Its validation that's failing two minutes after its email to the user.

Why its failing I can't tell as there is no logging.

Update:

I found this in the logging this morning.

System.Security.Cryptography.CryptographicException: The key {3f2b54f2-a87a-41aa-ad80-410b9edae1fd} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Xena.IdentityServer.Services.CustomDataProtectorTokenProvider`1.d__13.MoveNext() in /var/lib/jenkins/_xena-identityserver_master-GOXBVJ5FZB6XR4BFBDEOFNCAVTISFMJUP3YCSGLXO77AA655HWSQ/src/Xena.IdentityServer/Services/CustomDataProtectorTokenProvider.cs:line 113

So does this mean there is something wrong with Redis?

It looks like when a key is created it's not getting stored in the Redis cache. Can you try dumping the cache and see what's in it?

I will have to contact the server admin I don't have direct access to redis myself.

@blowdart I am in the process of getting access to the cluster so i can see this information. How soon after i see the error do you need me to dump the cache?

Just got another intersting error from my logging


System.FormatException: Invalid length for a Base-64 char array or string.
   at System.Convert.FromBase64_Decode(Char* startInputPtr, Int32 inputLength, Byte* startDestPtr, Int32 destLength)
   at System.Convert.FromBase64CharPtr(Char* inputPtr, Int32 inputLength)
   at System.Convert.FromBase64String(String s)
   at Xena.IdentityServer.Services.CustomDataProtectorTokenProvider`1.<ValidateAsync>d__13.MoveNext() in /var/lib/jenkins/_xena-identityserver_master-GOXBVJ5FZB6XR4BFBDEOFNCAVTISFMJUP3YCSGLXO77AA655HWSQ/src/Xena.IdentityServer/Services/CustomDataProtectorTokenProvider.cs:line 113

As that's identity server I have no insight as it's not us

Xena.IdentityServer.Services.CustomDataProtectorTokenProvider

That looks more like custom code in IdentityServer.

@brockallen if you are following the thread. As I mentioned in the last paragraph of this issue. I have created a CustomDataProtectorTokenProvider which is a pure copy of DataProtectionTokenProvider.cs simply adding some logging since the default version does not contain any logging.

There is no custom code in this. Its just logging so that we can try and track down what the issue is. without it the only loging information we have is

VerifyUserTokenAsync() failed with purpose: ResetPassword for user 289512195. | WARN | 9

@blowdart are you saying that because i am using Asp.net identity within Identity server 4 you cant help with the issue? Its your DataProtectionTokenProvider.cs How could Identity server 4 be at fault?

using Microsoft.AspNetCore.DataProtection;
using Microsoft.AspNetCore.Identity;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;
using System;
using System.IO;
using System.Text;
using System.Threading.Tasks;

namespace Xena.IdentityServer.Services
{
    public class CustomDataProtectorTokenProvider<TUser> : IUserTwoFactorTokenProvider<TUser> where TUser : class
    {
        private readonly ILogger<CustomDataProtectorTokenProvider<TUser>> _logger;

        /// <summary>
        /// Initializes a new instance of the <see cref="DataProtectorTokenProvider{TUser}"/> class.
        /// </summary>
        /// <param name="dataProtectionProvider">The system data protection provider.</param>
        /// <param name="options">The configured <see cref="DataProtectionTokenProviderOptions"/>.</param>
        public CustomDataProtectorTokenProvider(IDataProtectionProvider dataProtectionProvider, IOptions<DataProtectionTokenProviderOptions> options,
            ILogger<CustomDataProtectorTokenProvider<TUser>> logger)
        {
            if (dataProtectionProvider == null)
            {
                throw new ArgumentNullException(nameof(dataProtectionProvider));
            }

            _logger = logger;
            Options = options?.Value ?? new DataProtectionTokenProviderOptions();
            // Use the Name as the purpose which should usually be distinct from others
            Protector = dataProtectionProvider.CreateProtector(Name ?? "DataProtectorTokenProvider");
        }

        /// <summary>
        /// Gets the <see cref="DataProtectionTokenProviderOptions"/> for this instance.
        /// </summary>
        /// <value>
        /// The <see cref="DataProtectionTokenProviderOptions"/> for this instance.
        /// </value>
        protected DataProtectionTokenProviderOptions Options { get; private set; }

        /// <summary>
        /// Gets the <see cref="IDataProtector"/> for this instance.
        /// </summary>
        /// <value>
        /// The <see cref="IDataProtector"/> for this instance.
        /// </value>
        protected IDataProtector Protector { get; private set; }

        /// <summary>
        /// Gets the name of this instance.
        /// </summary>
        /// <value>
        /// The name of this instance.
        /// </value>
        public string Name { get { return Options.Name; } }

        /// <summary>
        /// Generates a protected token for the specified <paramref name="user"/> as an asynchronous operation.
        /// </summary>
        /// <param name="purpose">The purpose the token will be used for.</param>
        /// <param name="manager">The <see cref="UserManager{TUser}"/> to retrieve user properties from.</param>
        /// <param name="user">The <typeparamref name="TUser"/> the token will be generated from.</param>
        /// <returns>A <see cref="Task{TResult}"/> representing the generated token.</returns>
        public virtual async Task<string> GenerateAsync(string purpose, UserManager<TUser> manager, TUser user)
        {
            if (user == null)
            {
                throw new ArgumentNullException(nameof(user));
            }
            var ms = new MemoryStream();
            var userId = await manager.GetUserIdAsync(user);
            _logger.LogDebug(LoggingEvents.CustomDataProtectorTokenProviderCreate, "Generate token for [purpose:{purpose}] [userId:{userId}] ", purpose, userId);

            using (var writer = ms.CreateWriter())
            {
                writer.Write(DateTimeOffset.UtcNow);
                writer.Write(userId);
                writer.Write(purpose ?? "");
                string stamp = null;
                if (manager.SupportsUserSecurityStamp)
                {
                    stamp = await manager.GetSecurityStampAsync(user);
                    if (stamp == null)
                    {
                        await manager.UpdateSecurityStampAsync(user);
                        stamp = await manager.GetSecurityStampAsync(user);
                    }
                }
                writer.Write(stamp ?? "");
            }
            var protectedBytes = Protector.Protect(ms.ToArray());
            return Convert.ToBase64String(protectedBytes);
        }

        /// <summary>
        /// Validates the protected <paramref name="token"/> for the specified <paramref name="user"/> and <paramref name="purpose"/> as an asynchronous operation.
        /// </summary>
        /// <param name="purpose">The purpose the token was be used for.</param>
        /// <param name="token">The token to validate.</param>
        /// <param name="manager">The <see cref="UserManager{TUser}"/> to retrieve user properties from.</param>
        /// <param name="user">The <typeparamref name="TUser"/> the token was generated for.</param>
        /// <returns>
        /// A <see cref="Task{TResult}"/> that represents the result of the asynchronous validation,
        /// containing true if the token is valid, otherwise false.
        /// </returns>
        public virtual async Task<bool> ValidateAsync(string purpose, string token, UserManager<TUser> manager, TUser user)
        {
            try
            {
                var actualUserId = await manager.GetUserIdAsync(user);
                _logger.LogInformation(LoggingEvents.CustomDataProtectorTokenProviderValidate, "Validate token for [purpose:{purpose}] [actualUserId:{actualUserId}]", purpose, actualUserId);

                var unprotectedData = Protector.Unprotect(Convert.FromBase64String(token));
                var ms = new MemoryStream(unprotectedData);
                using (var reader = ms.CreateReader())
                {
                    var creationTime = reader.ReadDateTimeOffset();
                    var expirationTime = creationTime + Options.TokenLifespan;
                    _logger.LogDebug(LoggingEvents.CustomDataProtectorTokenProviderValidate, "Validate token for [actualUserId:{actualUserId}] [creationTime:{creationTime}] - [expirationTime:{expirationTime}]", actualUserId, creationTime, expirationTime);
                    if (expirationTime < DateTimeOffset.UtcNow)
                    {
                        _logger.LogWarning(LoggingEvents.CustomDataProtectorTokenProviderValidateFailed, "Token is expired [expirationTime:{expirationTime}]", expirationTime);
                        return false;
                    }
                    var userId = reader.ReadString();
                    if (userId != actualUserId)
                    {
                        _logger.LogWarning(LoggingEvents.CustomDataProtectorTokenProviderValidateFailed, "Token is not for this user [userId:{userId}] - [actualUserId:{actualUserId}]", userId, actualUserId);
                        return false;
                    }
                    var purp = reader.ReadString();
                    if (!string.Equals(purp, purpose))
                    {
                        _logger.LogWarning(LoggingEvents.CustomDataProtectorTokenProviderValidateFailed, "Token is for wrong purp [purp:{purp}] - [purpose:{purpose}]", purp, purpose);
                        return false;
                    }
                    var stamp = reader.ReadString();
                    if (reader.PeekChar() != -1)
                    {
                        _logger.LogWarning(LoggingEvents.CustomDataProtectorTokenProviderValidateFailed, "Token stamp not valid [stamp:{stamp}]", stamp);
                        return false;
                    }
                    if (manager.SupportsUserSecurityStamp)
                    {
                        return stamp == (await manager.GetSecurityStampAsync(user) ?? "");
                    }
                    return stamp == "";
                }
            }

            catch (Exception ex)
            {
                _logger.LogError(LoggingEvents.CustomDataProtectorTokenProviderValidateFailed, "Validate exception [ex:{ex}]", ex);
            }
            return false;
        }

        /// <summary>
        /// Returns a <see cref="bool"/> indicating whether a token generated by this instance
        /// can be used as a Two Factor Authentication token as an asynchronous operation.
        /// </summary>
        /// <param name="manager">The <see cref="UserManager{TUser}"/> to retrieve user properties from.</param>
        /// <param name="user">The <typeparamref name="TUser"/> the token was generated for.</param>
        /// <returns>
        /// A <see cref="Task{TResult}"/> that represents the result of the asynchronous query,
        /// containing true if a token generated by this instance can be used as a Two Factor Authentication token, otherwise false.
        /// </returns>
        /// <remarks>This method will always return false for instances of <see cref="DataProtectorTokenProvider{TUser}"/>.</remarks>
        public virtual Task<bool> CanGenerateTwoFactorTokenAsync(UserManager<TUser> manager, TUser user)
        {
            return Task.FromResult(false);
        }
    }

    /// <summary>
    /// Utility extensions to streams
    /// </summary>
    internal static class StreamExtensions
    {
        internal static readonly Encoding DefaultEncoding = new UTF8Encoding(false, true);

        public static BinaryReader CreateReader(this Stream stream)
        {
            return new BinaryReader(stream, DefaultEncoding, true);
        }

        public static BinaryWriter CreateWriter(this Stream stream)
        {
            return new BinaryWriter(stream, DefaultEncoding, true);
        }

        public static DateTimeOffset ReadDateTimeOffset(this BinaryReader reader)
        {
            return new DateTimeOffset(reader.ReadInt64(), TimeSpan.Zero);
        }

        public static void Write(this BinaryWriter writer, DateTimeOffset value)
        {
            writer.Write(value.UtcTicks);
        }
    }
}

aspnet / Identity

Random token invalid issue. #2020