Openiddict-core: Authentication failed because the access token was invalid

[m2017atTR]

OpenIddict 1.0.0-beta2-0608 working fine but ...
1.0.0-beta2-0612 gives error

I am working ower

https://github.com/asadsahi/AspNetCoreSpa

[kevinchalet]

What's the exact error you're seeing?

[m2017atTR]

And hey, thanks for very fast answer...
1.0.0-beta2-609, 611, 612 same result but 1.0.0-beta2-608 is _working_
in source of openiddict corresponding to ticket = null

Error like this..

Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request starting HTTP/1.1 GET http://localhost:5000/api/admin/doadminoperation application/json; charset=UTF-8 AspNet.Security.OAuth.Validation.OAuthValidationMiddleware:Information: Bearer was not authenticated. Failure message: Authentication failed because the access token was invalid. Microsoft.AspNetCore.Authorization.DefaultAuthorizationService:Information: Authorization failed for user: (null). Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Authorization failed for the request at filter 'Microsoft.AspNetCore.Mvc.Authorization.AuthorizeFilter'. Microsoft.AspNetCore.Mvc.ChallengeResult:Information: Executing ChallengeResult with authentication schemes (). AspNet.Security.OAuth.Validation.OAuthValidationMiddleware:Information: AuthenticationScheme: Bearer was challenged. Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action AspNetCoreSpa.Server.Controllers.api.AdminController.DoAdminOperation (AspNetCoreSpa) in 52.1373ms Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 67.4995ms 401

login part and getting token seems fine ..

Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request starting HTTP/1.1 POST http://localhost:5000/connect/token application/x-www-form-urlencoded 97 AspNet.Security.OpenIdConnect.Server.OpenIdConnectServerMiddleware:Information: The token request was successfully extracted from the HTTP request: { "username": "[email protected]", "password": "[removed for security reasons]", "grant_type": "password", "scope": "openid offline_access" }. AspNet.Security.OpenIdConnect.Server.OpenIdConnectServerMiddleware:Information: The token request was successfully validated. Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executing action method AspNetCoreSpa.Server.Controllers.api.AuthorizationController.Exchange (AspNetCoreSpa) with arguments ({ "username": "[email protected]", "password": "[removed for security reasons]", "grant_type": "password", "scope": "openid offline_access" }) - ModelState is Valid Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30'] PRAGMA foreign_keys=ON; Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[@__normalizedUserName_0='?'], CommandType='Text', CommandTimeout='30'] SELECT "u"."Id", "u"."AccessFailedCount", "u"."ConcurrencyStamp", "u"."CreatedDate", "u"."Email", "u"."EmailConfirmed", "u"."FirstName", "u"."IsEnabled", "u"."LastName", "u"."LockoutEnabled", "u"."LockoutEnd", "u"."NormalizedEmail", "u"."NormalizedUserName", "u"."PasswordHash", "u"."PhoneNumber", "u"."PhoneNumberConfirmed", "u"."SecurityStamp", "u"."TwoFactorEnabled", "u"."UserName" FROM "AspNetUsers" AS "u" WHERE "u"."NormalizedUserName" = @__normalizedUserName_0 LIMIT 1 Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30'] PRAGMA foreign_keys=ON; Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (1ms) [Parameters=[@__userId_0='?'], CommandType='Text', CommandTimeout='30'] SELECT "role"."Name" FROM "AspNetUserRoles" AS "userRole" INNER JOIN "AspNetRoles" AS "role" ON "userRole"."RoleId" = "role"."Id" WHERE "userRole"."UserId" = @__userId_0 Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30'] PRAGMA foreign_keys=ON; Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[@__normalizedName_0='?'], CommandType='Text', CommandTimeout='30'] SELECT "r"."Id", "r"."ConcurrencyStamp", "r"."Description", "r"."Name", "r"."NormalizedName" FROM "AspNetRoles" AS "r" WHERE "r"."NormalizedName" = @__normalizedName_0 LIMIT 1 Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30'] PRAGMA foreign_keys=ON; Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[@__role_Id_0='?'], CommandType='Text', CommandTimeout='30'] SELECT "rc"."ClaimType", "rc"."ClaimValue" FROM "AspNetRoleClaims" AS "rc" WHERE "rc"."RoleId" = @__role_Id_0 Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30'] PRAGMA foreign_keys=ON; Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[@__user_Id_0='?'], CommandType='Text', CommandTimeout='30'] SELECT "uc"."Id", "uc"."ClaimType", "uc"."ClaimValue", "uc"."UserId" FROM "AspNetUserClaims" AS "uc" WHERE "uc"."UserId" = @__user_Id_0 Microsoft.AspNetCore.Mvc.SignInResult:Information: Executing SignInResult with authentication scheme (ASOS) and the following principal: System.Security.Claims.ClaimsPrincipal. Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (0ms) [Parameters=[], CommandType='Text', CommandTimeout='30'] PRAGMA foreign_keys=ON; Microsoft.EntityFrameworkCore.Storage.IRelationalCommandBuilderFactory:Information: Executed DbCommand (7ms) [Parameters=[@p0='?', @p1='?', @p2='?', @p3='?', @p4='?'], CommandType='Text', CommandTimeout='30'] INSERT INTO "OpenIddictTokens" ("Id", "ApplicationId", "AuthorizationId", "Subject", "Type") VALUES (@p0, @p1, @p2, @p3, @p4); AspNet.Security.OpenIdConnect.Server.OpenIdConnectServerMiddleware:Information: The token response was successfully returned: { "token_type": "Bearer", "access_token": "[removed for security reasons]", "expires_in": 3600, "refresh_token": "[removed for security reasons]", "id_token": "[removed for security reasons]" }. AspNet.Security.OpenIdConnect.Server.OpenIdConnectServerMiddleware:Information: AuthenticationScheme: ASOS signed in. Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker:Information: Executed action AspNetCoreSpa.Server.Controllers.api.AuthorizationController.Exchange (AspNetCoreSpa) in 829.3022ms Microsoft.AspNetCore.Hosting.Internal.WebHost:Information: Request finished in 987.595ms 200 application/json;charset=UTF-8

[kevinchalet]

Actually, this is the expected behavior if you haven't updated the validation middleware to the RTM version (1.0.0), as OpenIddict itself has been updated to use ASOS 1.0.0, that only works with the 1.0.0 validation middleware.

Note that it's a deliberate choice (I didn't want to support weird ASOS 1.0.0/validation pre-RTM combinations). I'll write a blog post to mention this requirement in the next few days.

[kiwiingenuity]

I've made the change you suggested, but I'm still getting a "Authorization failed for user: null" response?
Is there some other action that needs to be done to get api calls working again?

[kevinchalet]

@kiwiingenuity could you please enable verbose logging (LogLevel.Trace) and post your traces? Make sure they contain nothing sensitive like user passwords.

[kiwiingenuity]

Verbose log attached.
api call line 1059

[kevinchalet]

I don't see logs indicating that the ASP.NET Core Data protection stack is trying to decrypt the access token. Did you remove some lines?

[kiwiingenuity]

I'm unsure if that data is missing because I have not set the loglevel correctly, so I tried again.

[kevinchalet]

Really weird, it looks like ASP.NET Core Data Protection is not even trying to decrypt the access token.

Any chance you could trace the HTTP calls using something like Fiddler? That would really help.

[kiwiingenuity]

Just so I understand better....

Below are some lines from a working sample. Not the application I've been sending you logs on to date.
Are the decrypt line present on the snippet below?

2017-05-12 09:25:02.315 +12:00 [Information] AuthenticationScheme: "ASOS" signed in.
2017-05-12 09:25:02.316 +12:00 [Information] Executed action "AspNetCoreSpa.Server.Controllers.api.AuthorizationController.Exchange (AspNetCoreSpa)" in 534.2643ms
2017-05-12 09:25:02.317 +12:00 [Debug] Connection id ""0HL4OMGH1727B"" completed keep alive response.
2017-05-12 09:25:02.317 +12:00 [Information] Request finished in 636.6032ms 200 application/json;charset=UTF-8
2017-05-12 09:25:07.448 +12:00 [Information] Request starting HTTP/1.1 GET http://localhost:5000/api/admin/doadminoperation application/json; charset=UTF-8
2017-05-12 09:25:07.449 +12:00 [Debug] The request path "" does not match the path filter
2017-05-12 09:25:07.449 +12:00 [Debug] The request path "/api/admin/doadminoperation" does not match a supported file type
2017-05-12 09:25:07.456 +12:00 [Verbose] Performing unprotect operation to key {eb4ee5e8-a05e-4947-b5b0-8fb87fafb868} with purposes "('F:\TempAspNetCoreSpa', 'OpenIdConnectServerHandler', 'AccessTokenFormat', 'ASOS')".
2017-05-12 09:25:07.471 +12:00 [Information] HttpContext.User merged via AutomaticAuthentication from authenticationScheme: "Bearer".
2017-05-12 09:25:07.471 +12:00 [Debug] Request successfully matched the route with name 'null' and template '"api/Admin/doadminoperation"'.
2017-05-12 09:25:07.472 +12:00 [Debug] Executing action "AspNetCoreSpa.Server.Controllers.api.AdminController.DoAdminOperation (AspNetCoreSpa)"
2017-05-12 09:25:07.485 +12:00 [Information] Authorization was successful for user: "[email protected]".
2017-05-12 09:25:07.486 +12:00 [Information] Executing action method "AspNetCoreSpa.Server.Controllers.api.AdminController.DoAdminOperation (AspNetCoreSpa)" with arguments (null) - ModelState is Valid
2017-05-12 09:25:07.486 +12:00 [Debug] Executed action method "AspNetCoreSpa.Server.Controllers.api.AdminController.DoAdminOperation (AspNetCoreSpa)", returned result "Microsoft.AspNetCore.Mvc.OkObjectResult".
2017-05-12 09:25:07.486 +12:00 [Debug] No information found on request to perform content negotiation.
2017-05-12 09:25:07.486 +12:00 [Debug] Selected output formatter '"Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter"' and content type '"application/json"' to write the response.
2017-05-12 09:25:07.486 +12:00 [Information] Executing ObjectResult, writing value "Microsoft.AspNetCore.Mvc.ControllerContext".
2017-05-12 09:25:07.489 +12:00 [Information] Executed action "AspNetCoreSpa.Server.Controllers.api.AdminController.DoAdminOperation (AspNetCoreSpa)" in 15.8929ms
2017-05-12 09:25:07.489 +12:00 [Debug] Connection id ""0HL4OMGH1727B"" completed keep alive response.
2017-05-12 09:25:07.490 +12:00 [Information] Request finished in 40.6859ms 200 application/json; charset=utf-8

[kevinchalet]

Are the decrypt line present on the snippet below?

Yes:

2017-05-12 09:25:07.456 +12:00 [Verbose] Performing unprotect operation to key {eb4ee5e8-a05e-4947-b5b0-8fb87fafb868} with purposes "('F:\Temp\AspNetCoreSpa', 'OpenIdConnectServerHandler', 'AccessTokenFormat', 'ASOS')".

Below are some lines from a working sample.

Interesting. What's the difference between this sample and the one that doesn't work? Different packages?

[kiwiingenuity]

That's the question I'm asking myself?
The main difference is that one package uses SqlLite and the other uses Sql Express.
Would you think that makes a difference?

[kevinchalet]

I really doubt it. I'll play with AspNetCoreSpa and see if I can reproduce the issue you're experiencing.

[kiwiingenuity]

Fiddler files attached

[kevinchalet]

Authorization: Bearer eyJhbGciOiJSUzI1NiIsImtpZCI6IlhPSEFXREJHSE8yWVVCVEVJT1ZaUDgySkdSX1BQWjVKUDVWNkRDU1EiLCJ0eXAiOiJKV1QifQ.eyJzdWIiOiI5IiwibmFtZSI6InVzZXJAdXNlci5jb20iLCJBc3BOZXQuSWRlbnRpdHkuU2VjdXJpdHlTdGFtcCI6Ijk3ZGFmNzEyLTFhMjAtNGY4Zi04ZThjLTM1ZTc3ODk5Yjc2ZSIsInJvbGUiOiJVc2VyIiwiZ2l2ZW5fbmFtZSI6IkFsbGFuIiwiZmFtaWx5X25hbWUiOiJXaXNzaW5nIiwidXNhZ2UiOiJpZGVudGl0eV90b2tlbiIsImp0aSI6IjM3YzJiMDM4LWZiNDEtNGYxYi1hNWRlLTlkMDg1NmE2MzQ0YiIsImF0X2hhc2giOiJtUHlfQnJ3bzlqNTV0dGhNMHZJS0NRIiwibmJmIjoxNDk0NTQxMjI0LCJleHAiOjE0OTQ1NDI0MjQsImlhdCI6MTQ5NDU0MTIyNCwiaXNzIjoiaHR0cDovL2xvY2FsaG9zdDo1MDAwLyJ9.M1QI-b1dy3UpA7TYSN5EjbWAZ5Jh_i7bTB1z26wshdzfrtS0mGh_mg5hU2ySHh6w81REbTDUVHL8PYD-O1NPG5rfL0cuJDvIEW_vzrAIIc9B6XE4IK2SV0IDQ2E5_u2U8EmNBWnSs0qHxwIGAtAZWK93jg4HYLqr0wFna9hU4GLp74Oc03dEHsgTbcOxi0TPZw2LqhFYJlCE4xU7gQE7m17lmmq5kn09zj8mEPG-0TShVB5H8i0g0Z7cIEj3cgNHEc2T9KUiWdqNNo8Pi9VSRdtDk2l2-8HTIRbEqjM9TmxEAm_e3Fg-QAepQN0D2Nz2H5h5SpCzDIYHTF40_uyzrA

You're trying to use the JWT identity token as an access token, which cannot work. Send the access token and it should work.

Note: it looks like you're not using the latest bits that were pushed to NuGet. Consider clearing your packages as explained in this post: http://kevinchalet.com/2017/05/08/aspnet-security-openidconnect-server-1-0-0-general-availability/

[kiwiingenuity]

In the AspNetCoreSpa app
See https://github.com/asadsahi/AspNetCoreSpa/blob/master/Client/app/core/services/data.service.ts#L129
Are you saying this is wrong?

[kevinchalet]

This line is correct, but what your own code is doing is likely wrong, as it's the identity (not access) token that ends up being sent to the API.

[kiwiingenuity]

That was it!
Yes I did change that line while debugging last week and DIDN"T CHANGE IT BACK!
Thank-you for your help!
I'll action the items in your blog and start going into productive mode again!