Antiforgery Token could not be decrypted

[vankampenp]

This seems related to this issue: aspnet/DataProtection#233

On my production server, even under small load, I am getting decryption errors in the log:
Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgery: An exception was thrown while deserializing the token. The antiforgery token could not be decrypted.

I am using Microsoft.AspNetCore.All 2.0.5

With the workaround described in the mentioned issue, the problem goes away

[mkArtakMSFT]

@natemcmaster, did we regress this? According to the referenced issue this has been fixed a while ago.

[natemcmaster]

There are lots of reasons a token could not be decrypted. I would need to see more details. cc @blowdart

[mkArtakMSFT]

@vankampenp , can you please share with us a small repro project, so we can investigate it? Thanks!

[vankampenp]

It is a bit hard to make a repro project and try it on the production server. I do have more info. Please see the log of the event below. Please let me know if this helps. Otherwize I can try to find the smallest repro project. I first had [AutoValidateAntiforgeryToken] on the controller and removed that to see if the problem was related to that, as it seems that it is trying to get an AntiforgeryToken on an HttpGet method.

[HttpGet] [AllowAnonymous] public async Task<IActionResult> Index([...
Base.Index: What is happening is the user is recognized from id info on a link, and a (temp) user is created. The user is than signed in to this temp user. After this there is a localredirect:
return LocalRedirect(Url.Action("start"));

[HttpGet] [Authorize(Roles = DtoRoles.Client)] [Route("klaar")] [Route("finished")] [Route("start")] public async Task<IActionResult> SwitchBoard() {

In the log, I see the arrival at method SwitchBoard(), with ModelState valid.
Here the AntiForgeryToken cannot be decrypted, eventhough there should not be an AntiForgeryToken on the HttpGet

2018-02-14 12:35:54.9853|<ipaddress>||INFO |7.6.3.0||DTOWEB.Controllers.BaseController|Base|<Index>d__10.MoveNext|Client login from link { SessionId = <id>, LanguageId = nl, Browser = Chrome, BrowserVersion = 63.0.3239.132, OS = Mac OS, OSversion = OS X 10.13.3, siteVersion = 7.6.3.0 } 
2018-02-14 12:35:54.9853|<ipaddress>||INFO |7.6.3.0||Microsoft.AspNetCore.Mvc.Internal.LocalRedirectResultExecutor|Base|Logger.Log|Executing LocalRedirectResult, redirecting to /start. 
2018-02-14 12:35:54.9853|<ipaddress>||INFO |7.6.3.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|Logger.Log|Executed action DTOWEB.Controllers.BaseController.Index (DTOWEB) in 142.721ms 
2018-02-14 12:35:54.9853|<ipaddress>||INFO |7.6.3.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|Base|Logger.Log|Request finished in 146.3311ms 302  
2018-02-14 12:35:55.0228|127.0.0.1||INFO |7.6.3.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||Logger.Log|Request starting HTTP/1.1 GET http://www.testmij.nl/start   
2018-02-14 12:35:55.0228|<ipaddress>||INFO |7.6.3.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler||Logger.Log|AuthenticationScheme: Identity.Application was successfully authenticated. 
2018-02-14 12:35:55.0228|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Authorization.DefaultAuthorizationService|Base|Logger.Log|Authorization was successful for user: <username>. 
2018-02-14 12:35:55.0228|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Authorization.DefaultAuthorizationService|Base|Logger.Log|Authorization was successful for user: <username>. 
2018-02-14 12:35:55.0228|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|Logger.Log|Executing action method DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB) with arguments ((null)) - ModelState is Valid 
2018-02-14 12:35:55.0228|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.EntityFrameworkCore.Infrastructure|Base|Logger.Log|Entity Framework Core 2.0.1-rtm-125 initialized 'DTOIdentityDBContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer' with options: None 
2018-02-14 12:35:55.0337|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.EntityFrameworkCore.Database.Command|Base|Logger.Log|Executed DbCommand (1ms) [Parameters=[@__get_Item_0='?' (Size = 450)], CommandType='Text', CommandTimeout='30']
SELECT TOP(1) [e].[Id], [e].[AccessFailedCount], [e].[ConcurrencyStamp], [e].[DateDeleted], [e].[DepartmentId], [e].[DisplayName], [e].[DtoClientId], [e].[DtoId], [e].[Email], [e].[EmailConfirmed], [e].[EmailInvite], [e].[EpdId], [e].[GenderId], [e].[IsMain], [e].[IsRom], [e].[LanguageId], [e].[LastLogin], [e].[LockoutEnabled], [e].[LockoutEnd], [e].[NormalizedEmail], [e].[NormalizedUserName], [e].[PasswordHash], [e].[PhoneNumber], [e].[PhoneNumberConfirmed], [e].[SecurityStamp], [e].[Sleutel], [e].[TestId], [e].[TwoFactorEnabled], [e].[UserName], [e].[Warned], [e].[ZoCode]
FROM [AspNetUsers] AS [e]
WHERE [e].[Id] = @__get_Item_0 
2018-02-14 12:35:55.0337|<ipaddress>|<username>|TRACE|7.6.3.0||DTOWEB.Controllers.BaseController|Base|<SwitchBoard>d__23.MoveNext|/start 
2018-02-14 12:35:55.0337|<ipaddress>|<username>|TRACE|7.6.3.0||DTOWEB.Sessions|Base|Sessions.FindTestsByClientId|selected = 1 in 6,2412 ms 
2018-02-14 12:35:55.0514|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.EntityFrameworkCore.Database.Command|Base|Logger.Log|Executed DbCommand (1ms) [Parameters=[@__normalizedUserName_0='?' (Size = 256)], CommandType='Text', CommandTimeout='30']
SELECT TOP(1) [u].[Id], [u].[AccessFailedCount], [u].[ConcurrencyStamp], [u].[DateDeleted], [u].[DepartmentId], [u].[DisplayName], [u].[DtoClientId], [u].[DtoId], [u].[Email], [u].[EmailConfirmed], [u].[EmailInvite], [u].[EpdId], [u].[GenderId], [u].[IsMain], [u].[IsRom], [u].[LanguageId], [u].[LastLogin], [u].[LockoutEnabled], [u].[LockoutEnd], [u].[NormalizedEmail], [u].[NormalizedUserName], [u].[PasswordHash], [u].[PhoneNumber], [u].[PhoneNumberConfirmed], [u].[SecurityStamp], [u].[Sleutel], [u].[TestId], [u].[TwoFactorEnabled], [u].[UserName], [u].[Warned], [u].[ZoCode]
FROM [AspNetUsers] AS [u]
WHERE [u].[NormalizedUserName] = @__normalizedUserName_0 
2018-02-14 12:35:55.0514|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.EntityFrameworkCore.Database.Command|Base|Logger.Log|Executed DbCommand (1ms) [Parameters=[@__normalizedEmail_0='?' (Size = 256)], CommandType='Text', CommandTimeout='30']
SELECT TOP(1) [u].[Id], [u].[AccessFailedCount], [u].[ConcurrencyStamp], [u].[DateDeleted], [u].[DepartmentId], [u].[DisplayName], [u].[DtoClientId], [u].[DtoId], [u].[Email], [u].[EmailConfirmed], [u].[EmailInvite], [u].[EpdId], [u].[GenderId], [u].[IsMain], [u].[IsRom], [u].[LanguageId], [u].[LastLogin], [u].[LockoutEnabled], [u].[LockoutEnd], [u].[NormalizedEmail], [u].[NormalizedUserName], [u].[PasswordHash], [u].[PhoneNumber], [u].[PhoneNumberConfirmed], [u].[SecurityStamp], [u].[Sleutel], [u].[TestId], [u].[TwoFactorEnabled], [u].[UserName], [u].[Warned], [u].[ZoCode]
FROM [AspNetUsers] AS [u]
WHERE [u].[NormalizedEmail] = @__normalizedEmail_0 
2018-02-14 12:35:55.0514|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.EntityFrameworkCore.Database.Command|Base|Logger.Log|Executed DbCommand (1ms) [Parameters=[@p30='?' (Size = 450), @p0='?', @p1='?' (Size = 4000), @p31='?' (Size = 4000), @p2='?', @p3='?', @p4='?' (Size = 4000), @p5='?', @p6='?', @p7='?' (Size = 256), @p8='?', @p9='?' (Size = 4000), @p10='?', @p11='?', @p12='?', @p13='?', @p14='?' (Size = 4000), @p15='?', @p16='?', @p17='?', @p18='?' (Size = 256), @p19='?' (Size = 256), @p20='?' (Size = 4000), @p21='?' (Size = 4000), @p22='?', @p23='?' (Size = 4000), @p24='?' (Size = 4000), @p25='?' (Size = 4000), @p26='?', @p27='?' (Size = 256), @p28='?' (Size = 4000), @p29='?' (Size = 4000)], CommandType='Text', CommandTimeout='30']
SET NOCOUNT ON;
UPDATE [AspNetUsers] SET [AccessFailedCount] = @p0, [ConcurrencyStamp] = @p1, [DateDeleted] = @p2, [DepartmentId] = @p3, [DisplayName] = @p4, [DtoClientId] = @p5, [DtoId] = @p6, [Email] = @p7, [EmailConfirmed] = @p8, [EmailInvite] = @p9, [EpdId] = @p10, [GenderId] = @p11, [IsMain] = @p12, [IsRom] = @p13, [LanguageId] = @p14, [LastLogin] = @p15, [LockoutEnabled] = @p16, [LockoutEnd] = @p17, [NormalizedEmail] = @p18, [NormalizedUserName] = @p19, [PasswordHash] = @p20, [PhoneNumber] = @p21, [PhoneNumberConfirmed] = @p22, [SecurityStamp] = @p23, [Sleutel] = @p24, [TestId] = @p25, [TwoFactorEnabled] = @p26, [UserName] = @p27, [Warned] = @p28, [ZoCode] = @p29
WHERE [Id] = @p30 AND [ConcurrencyStamp] = @p31;
SELECT @@ROWCOUNT; 
2018-02-14 12:35:55.0661|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.ViewResultExecutor|Base|Logger.Log|Executing ViewResult, running view at path /Views/Base/switchboard.cshtml. `
**`2018-02-14 12:35:55.1563|<ipaddress>|<username>|ERROR|7.6.3.0||Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgery|Base|Logger.Log|An exception was thrown while deserializing the token. The antiforgery token could not be decrypted.`**
`2018-02-14 12:35:55.1711|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Base|Logger.Log|Executed action DTOWEB.Controllers.BaseController.SwitchBoard (DTOWEB) in 145.6281ms 
2018-02-14 12:35:55.1780|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Hosting.Internal.WebHost|Base|Logger.Log|Request finished in 155.2305ms 200 text/html; charset=utf-8 
2018-02-14 12:35:55.5294|127.0.0.1||INFO |7.6.3.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||Logger.Log|Request starting HTTP/1.1 GET http://www.testmij.nl/images/icons/favicon-32x32.png   
2018-02-14 12:35:55.5294|<ipaddress>||INFO |7.6.3.0||Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationHandler||Logger.Log|AuthenticationScheme: Identity.Application was successfully authenticated. 
2018-02-14 12:35:55.5328|<ipaddress>|<username>|INFO |7.6.3.0||Microsoft.AspNetCore.Hosting.Internal.WebHost||Logger.Log|Request finished in 3.3897ms 302  

[blowdart]

Is this a SPA app by any chance?

[vankampenp]

It is multi-page, with the html rendered server side as razor pages. But there are some SPA like aspect, such as loading the pages through AJAX, and having one entry point to the app (with no user links).
However, in the part where it has the error above, there is no AJAX loading yet.
BaseController.Index in most cases would return Index.cshml, but in this particular use case redirects to BaseController.SwitchBoard.

[natemcmaster]

@vankampenp can you provide more information about how you have configured data protection? This error normally appears when the keys used by antiforgery change between the time the antiforgery token was created and when it was decrypted. Some indications this may be happening:

• The log contains WARNING messages about ephemeral keys. Warnings say something like "Using ephemeral data protection provider" or "Neither user profile nor HKLM registry available. Using an ephemeral key repository"

  This is most common when running in Docker.

• When the server restarts, it is unable to reload existing keys, so it creates new keys. Old antiforgery tokens cannot be decrypted with the new keys. If this is happening, the log would contain an INFO level message that says "Creating key ..." each time you restart the server. You can ensure this isn't the case by disabling automatic key generation.

• (Less common) You have multiple instances of the server running. The server decrypting the anti-forgery token is not the same server that created then token.

Are any of these true of your app?

[vankampenp]

@natemcmaster

1. I am running on a shared host, not Docker.

2. I have a single server

3. Not sure about this. However, the error did not occur on a HttpPost, but on a HttpGet, where it should not even try to decrypt a token. It can't decrypt it, because the token is not submitted to the server on a HttpGet.

[natemcmaster]

However, the error did not occur on a HttpPost, but on a HttpGet, where it should not even try to decrypt a token. It can't decrypt it, because the token is not submitted to the server on a HttpGet.

@vankampenp it's hard to investigate this further because we still don't have an way to reproduce the error. From what you've described, it could be:

• a bug in MVC. Antiforgery validation is happening even though it shouldn't. As you correctly mentioned, GET requests should be ignored by the validation when the AutoValidateAntiforgeryToken filter is used
• a misconfiguration of the app. If the ValidateAntiforgeryToken filter is being applied, this would still run on GET requests
• some other bug in antiforgery. It's possible something in antiforgery is not reading the cookie/tokens/headers correctly
• a misconfiguration of data protection. The correct tokens may be present, but data protection may be having an issue decrypting the contents of the tokens. This could happen if keys are missing.
• And more...

@mkArtakMSFT regardless, there is still an actionable item here. We could add add more details to the log mesage about what happened. The place where the error comes from may have an inner exception. When present, we should consider logging the message from that inner exception to give us more clues about what is going wrong.

https://github.com/aspnet/Antiforgery/blob/26f65bd70e3f9f8b3bea1c03f96b6c606726b277/src/Microsoft.AspNetCore.Antiforgery/Internal/DefaultAntiforgeryTokenSerializer.cs#L78

[natemcmaster]

@mkArtakMSFT un-assigning myself from further investigation. Without a repro, I cannot make progress on this.

[mkArtakMSFT]

Thanks @natemcmaster.

[mkArtakMSFT]

Closing this issue as it seems there is no repro and we have no way to investigate the reported behavior. Feel free to reopen if, when you'll get more info which can help with investigation.

[changhuixu]

I get this type of error frequently...

2018-10-01 12:41:11 [EROR] [Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgery] An exception was thrown while deserializing the token.
Microsoft.AspNetCore.Antiforgery.AntiforgeryValidationException: The antiforgery token could not be decrypted. ---> System.Security.Cryptography.CryptographicException: The key {e8076ac1-2efa-4891-a851-78f3d9ca5710} 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 Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgeryTokenSerializer.Deserialize(String serializedToken)
   --- End of inner exception stack trace ---
   at Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgeryTokenSerializer.Deserialize(String serializedToken)
   at Microsoft.AspNetCore.Antiforgery.Internal.DefaultAntiforgery.GetCookieTokenDoesNotThrow(HttpContext httpContext)

I am using [AutoValidateAntiforgeryToken] for all controllers and the client side app is an Angular SPA.
SetUp.cs

services.AddAntiforgery(options => options.HeaderName = "X-XSRF-TOKEN");
...
app.UseAntiforgeryToken();

 public class AntiforgeryTokenMiddleware
    {
        private readonly RequestDelegate _next;
        private readonly IAntiforgery _antiforgery;

        public AntiforgeryTokenMiddleware(RequestDelegate next, IAntiforgery antiforgery)
        {
            _next = next;
            _antiforgery = antiforgery;
        }

        public Task Invoke(HttpContext context)
        {
            var path = context.Request.Path.Value?.ToLower() ?? string.Empty;

            if (path.StartsWith("/account") || path.StartsWith("/api"))
            {
                var tokens = _antiforgery.GetAndStoreTokens(context);
                context.Response.Cookies.Append("XSRF-TOKEN", tokens.RequestToken,
                    new CookieOptions() { HttpOnly = false });
            }
            return _next(context);
        }
    }

    public static class AntiforgeryTokenMiddlewareExtensions
    {
        public static IApplicationBuilder UseAntiforgeryToken(this IApplicationBuilder builder)
        {
            return builder.UseMiddleware<AntiforgeryTokenMiddleware>();
        }
    }

I am still watching the pattern when the error occurs.
Currently, when the application first time starts, the exception will throw.
However, exception will throw at some random times too.

I strongly suspect that the end point that triggers the exception is in /account/user GET method. Because the exception always throw after the application get user information.

[vankampenp]

As a workaround, I am still using the solution described here aspnet/DataProtection#233. Not sure this is still needed in 2.1, but I am hesitant to remove it.
In any case, I am no longer having these issues with that workaround.