search

IdentityServer / IdentityServer4

OpenID Connect and OAuth 2.0 Framework for ASP.NET Core
https://identityserver.io
Apache License 2.0
9.23k stars 4.02k forks source link

I always get invalid_grant when doing a refresh_token #1784

Closed diomedtmc closed 6 years ago

diomedtmc commented 6 years ago

- [ ] I read and understood how to enable logging

Note that my client is setup for multiple refreshes of the token.

Issue / Steps to reproduce the problem

  1. Create an "offline" scope token use grant_type=password
  2. Use grant_type=refresh_token to try and refresh using the refresh_key from #1

Will get invalid_grant here. It says the token is expired - what I have done wrong? The original issue was just seconds before the refresh.

Relevant parts of the log file

2017-11-21 13:02:33.166 -08:00 [VRB] Creating token response
2017-11-21 13:02:33.168 -08:00 [VRB] Processing token request
2017-11-21 13:02:33.175 -08:00 [VRB] Creating access token
2017-11-21 13:02:33.181 -08:00 [DBG] Getting claims for access token for client: 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc
2017-11-21 13:02:33.181 -08:00 [DBG] Getting claims for access token for subject: 2f3b1a80-2a89-428f-80be-2a86b6a97299
2017-11-21 13:02:33.195 -08:00 [DBG] Claim types from profile service that were filtered: ["sub","idp","amr","auth_time"]
2017-11-21 13:02:33.199 -08:00 [VRB] Creating JWT access token
2017-11-21 13:02:33.333 -08:00 [DBG] Creating refresh token
2017-11-21 13:02:33.333 -08:00 [DBG] Setting an absolute lifetime: 960
2017-11-21 13:02:33.365 -08:00 [DBG] ++NJCTejDHNhgK2Sq6o+Q/SNhTsS+wUwOPx1jcUh648= converting to entity
2017-11-21 13:02:33.369 -08:00 [DBG] ++NJCTejDHNhgK2Sq6o+Q/SNhTsS+wUwOPx1jcUh648= updating in database
2017-11-21 13:02:33.518 -08:00 [VRB] Refresh token issued for 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc (no name set) / 2f3b1a80-2a89-428f-80be-2a86b6a97299: 8054fa26dd476c11058f878c903895508e80a3c14ae12a260dc4c51eab4ee6bd
2017-11-21 13:02:33.518 -08:00 [VRB] Access token issued for 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc (no name set) / 2f3b1a80-2a89-428f-80be-2a86b6a97299: eyJhbGciOiJSUzI1NiIsImtpZCI6IkFEQUE3NDdGREZGNEEzQ0E2NTQ3QzAzMUUzRUNGQ0Q5QzIwOTgxN0UiLCJ0eXAiOiJKV1QiLCJ4NXQiOiJyYXAwZjlfMG84cGxSOEF4NC16ODJjSUpnWDQifQ.eyJuYmYiOjE1MTEyOTgxNTMsImV4cCI6MTUxMTI5OTExMywiaXNzIjoiaHR0cDovL2xvY2FsaG9zdDo0OTgzOSIsImF1ZCI6Imh0dHA6Ly9sb2NhbGhvc3Q6NDk4MzkvcmVzb3VyY2VzIiwiY2xpZW50X2lkIjoiOWY1OTdiMGItYmE2NC00MWI4LWJlNmUtYWViN2QyZTc5NmZjIiwic3ViIjoiMmYzYjFhODAtMmE4OS00MjhmLTgwYmUtMmE4NmI2YTk3Mjk5IiwiYXV0aF90aW1lIjoiNjM2NDY4OTQ5NTMxNTI5NjY4IiwiaWRwIjoiaHR0cHM6Ly9sb2dpbi53aW5kb3dzLm5ldCIsInByZWZlcnJlZF91c2VybmFtZSI6IlRlc3QgUmV2aWV3ZXIgMSIsIm5hbWUiOiJ0ZWNoMUBlcGljc2NpZW5jZXMuY29tIiwiZW1haWwiOiIiLCJyb2xlIjpbIlNURyIsIlJldmlld2VyIiwiREVWIiwiU1FFIl0sImp0aSI6IjRlNjkzNDY5MmVkODFkYzQ0MGJjOWFhZTNhYmFlZTE1Iiwic2NvcGUiOlsiZW1haWwiLCJvcGVuaWQiLCJwcm9maWxlIiwicm91dGVyLmZ1bGxfYWNjZXNzIiwib2ZmbGluZV9hY2Nlc3MiXSwiYW1yIjpbInBhc3N3b3JkIl19.huxwoUDv4XU1WyJboPSyzML29YYSM12RvLp7sJX4TUaDOXnenCFKKL0g1uuRMJKivBPOGjtNpe0TLg0QkwqDDHnDIfDUZzVGvBsE2_5_oRNsDqPjQOO_4Z_pq0nta8ZgiSBbk7dUGs3BB3qgvi9JXoPXw-fYX4LFHXVIHAOIsVzJEG7jJIn2U6ZLXyChPsFIllvhLOk_TFo96nyAC_5ARPP3H5-wxSm-nTA1KBQnrkgbqrqo44MX0zecH9yMGCjSj7gYVuwRda8CNLgaFcm214jftour-76NzkidQmXuUGGW0VMdnNYEKJAUUcmmI5ilqlbhMrps_BtJG8u02vj6slpWxAeAAbGt2rd3Z1zg4LNmla0MsRmGFnGBuRHq4sg7cdkpWtFsYZNQUDRTs0qk4w2C4oy2gANHgGJM0q61vWlCABagQAObTJX7ttKcrVDJvOnfC19Rl7JNlBQSejAP3czJZ4siiwy7ChQ5qvH10CxQNL1k8spGwVY8lNP0lLzB_qG2d3-PT-kIJIHv2dUBKjEFPi4jfhhVBIEqdIH-Yozp0Hyo9MIl9fxFPaiu3d4qnqjPTR-LOQ7-7tf3RfnOufpQpoaEDG4_dCqM-PVQxyEiAS1ihyRroIjWHl9ti6M-y6nIiXQyEz4RP5VLeENDukfli9bNqQEVnb7MaGvsE_s
2017-11-21 13:02:33.518 -08:00 [DBG] Token request success.
2017-11-21 13:02:33.519 -08:00 [VRB] Invoking result: IdentityServer4.Endpoints.Results.TokenResult
2017-11-21 13:02:33.525 -08:00 [DBG] Connection id "0HL9H4BL46BE2" completed keep alive response.
2017-11-21 13:02:33.525 -08:00 [INF] Request finished in 4024.9588ms 200 application/json
2017-11-21 13:02:49.050 -08:00 [INF] Request starting HTTP/1.1 POST http://localhost:49839/connect/token application/x-www-form-urlencoded 201
2017-11-21 13:02:49.050 -08:00 [DBG] AuthenticationScheme: idsrv was not authenticated.
2017-11-21 13:02:49.050 -08:00 [DBG] Request path /connect/token matched to endpoint type "Token"
2017-11-21 13:02:49.050 -08:00 [DBG] Mapping found for endpoint: "Token", creating handler: IdentityServer4.Endpoints.TokenEndpoint
2017-11-21 13:02:49.050 -08:00 [INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.TokenEndpoint for /connect/token
2017-11-21 13:02:49.050 -08:00 [VRB] Processing token request.
017-11-21 13:02:49.050 -08:00 [DBG] Start token request.
2017-11-21 13:02:49.050 -08:00 [DBG] Start client validation
2017-11-21 13:02:49.050 -08:00 [DBG] Start parsing Basic Authentication secret
2017-11-21 13:02:49.050 -08:00 [DBG] Start parsing for secret in post body
2017-11-21 13:02:49.056 -08:00 [DBG] Parser found secret: PostBodySecretParser
2017-11-21 13:02:49.056 -08:00 [DBG] Secret id found: 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc
2017-11-21 13:02:49.056 -08:00 [DBG] 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc found in database: true
2017-11-21 13:02:49.056 -08:00 [DBG] Public Client - skipping secret validation success
2017-11-21 13:02:49.056 -08:00 [DBG] Client validation success
2017-11-21 13:02:49.056 -08:00 [DBG] Start token request validation
2017-11-21 13:02:49.056 -08:00 [DBG] Start validation of refresh token request
2017-11-21 13:02:49.208 -08:00 [DBG] ++NJCTejDHNhgK2Sq6o+Q/SNhTsS+wUwOPx1jcUh648= found in database: true
2017-11-21 13:02:56.897 -08:00 [DBG] refresh_token grant with value: 8054fa26dd476c11058f878c903895508e80a3c14ae12a260dc4c51eab4ee6bd found in store, but has expired.
2017-11-21 13:02:56.897 -08:00 [ERR] Invalid refresh token: 8054fa26dd476c11058f878c903895508e80a3c14ae12a260dc4c51eab4ee6bd
2017-11-21 13:02:56.897 -08:00 [ERR] {
  "ClientId": "9f597b0b-ba64-41b8-be6e-aeb7d2e796fc",
  "GrantType": "refresh_token",
  "RefreshToken": "8054fa26dd476c11058f878c903895508e80a3c14ae12a260dc4c51eab4ee6bd",
  "Raw": {
    "grant_type": "refresh_token",
    "client_id": "9f597b0b-ba64-41b8-be6e-aeb7d2e796fc",
    "client_secret": "", //REMOVED FOR SECURITY
    "refresh_token": "8054fa26dd476c11058f878c903895508e80a3c14ae12a260dc4c51eab4ee6bd"
  }
}
2017-11-21 13:02:56.897 -08:00 [VRB] Invoking result: IdentityServer4.Endpoints.Results.TokenErrorResult
2017-11-21 13:02:56.897 -08:00 [DBG] Connection id "0HL9H4BL46BE2" completed keep alive response.
2017-11-21 13:02:56.897 -08:00 [INF] Request finished in 7848.0124ms 400 application/json

Stepping through the code indicates that the token indeed exists is loaded correctly in its IPersistedGrantStore.GetAsync method.

chrisdrobison commented 6 years ago

Have you enabled the ability on the client? There is a flag called AllowOfflineAccess (or something close to that) that you need to set to true. On Tue, Nov 21, 2017 at 1:54 PM diomedtmc notifications@github.com wrote:

Note that my client is setup for multiple refreshes of the token. Issue / Steps to reproduce the problem

  1. Create an "offline" scope token use grant_type=password
  2. Use grant_type=refresh_token to try and refresh

Will get invalid_grant here. Its like the whole thing is broken. Relevant parts of the log file

2017-11-21 12:47:21.437 -08:00 [ERR] Invalid refresh token: c2c274a68fc25ac54a309ca8b4e6ae9207fff65b102090fc5db5357250b13d98 2017-11-21 12:47:22.010 -08:00 [ERR] { "ClientId": "9f597b0b-ba64-41b8-be6e-aeb7d2e796fc", "GrantType": "refresh_token", "RefreshToken": "c2c274a68fc25ac54a309ca8b4e6ae9207fff65b102090fc5db5357250b13d98", "Raw": { "grant_type": "refresh_token", "client_id": "9f597b0b-ba64-41b8-be6e-aeb7d2e796fc", "client_secret": "", //REMOVED FOR SECURITY "refresh_token": "c2c274a68fc25ac54a309ca8b4e6ae9207fff65b102090fc5db5357250b13d98" } }

Stepping through the code indicates that the token indeed exists is loaded correctly in its GetByKey method.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/IdentityServer/IdentityServer4/issues/1784, or mute the thread https://github.com/notifications/unsubscribe-auth/ABu24bhqjUEOUYhi9gTUWkn_2peESh9Bks5s4zhogaJpZM4QmeMr .

brockallen commented 6 years ago

2017-11-21 13:02:56.897 -08:00 [DBG] refresh_token grant with value: 8054fa26dd476c11058f878c903895508e80a3c14ae12a260dc4c51eab4ee6bd found in store, but has expired.

This is your error.

diomedtmc commented 6 years ago

I see that, but my expiration is valid in other places. I ran that call like 15 seconds after creating the original grant. 16 minute token, it should still be good. Why does the server think it is invalid during refresh? (Take the token value and use it in Jwt.io, Expiration should have been valid) Am I missing a time conversion or something?

diomedtmc commented 6 years ago

Same thing here:

2017-11-21 13:18:39.964 -08:00 [VRB] Creating token response 2017-11-21 13:18:39.966 -08:00 [VRB] Processing token request 2017-11-21 13:18:39.975 -08:00 [VRB] Creating access token 2017-11-21 13:18:39.983 -08:00 [DBG] Getting claims for access token for client: 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc 2017-11-21 13:18:39.983 -08:00 [DBG] Getting claims for access token for subject: 2f3b1a80-2a89-428f-80be-2a86b6a97299 2017-11-21 13:18:39.995 -08:00 [DBG] Claim types from profile service that were filtered: ["sub","idp","amr","auth_time"] 2017-11-21 13:18:40.001 -08:00 [VRB] Creating JWT access token 2017-11-21 13:18:40.172 -08:00 [DBG] Creating refresh token 2017-11-21 13:18:40.172 -08:00 [DBG] Setting an absolute lifetime: 960 2017-11-21 13:18:40.215 -08:00 [DBG] e/Dm2lN+CkIGD7Mf6Xge9h6Kno0pdyO2pJLfE7ok6V0= converting to entity 2017-11-21 13:18:40.225 -08:00 [DBG] e/Dm2lN+CkIGD7Mf6Xge9h6Kno0pdyO2pJLfE7ok6V0= updating in database 2017-11-21 13:18:40.472 -08:00 [VRB] Refresh token issued for 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc (no name set) / 2f3b1a80-2a89-428f-80be-2a86b6a97299: fe8dfc8820159e3ec9038cb677094a66df8e09c841458617d54232cf2f4359bd 2017-11-21 13:18:40.472 -08:00 [VRB] Access token issued for 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc (no name set) / 2f3b1a80-2a89-428f-80be-2a86b6a97299: eyJhbGciOiJSUzI1NiIsImtpZCI6IkFEQUE3NDdGREZGNEEzQ0E2NTQ3QzAzMUUzRUNGQ0Q5QzIwOTgxN0UiLCJ0eXAiOiJKV1QiLCJ4NXQiOiJyYXAwZjlfMG84cGxSOEF4NC16ODJjSUpnWDQifQ.eyJuYmYiOjE1MTEyOTkxMjAsImV4cCI6MTUxMTMwMDA4MCwiaXNzIjoiaHR0cDovL2xvY2FsaG9zdDo0OTgzOSIsImF1ZCI6Imh0dHA6Ly9sb2NhbGhvc3Q6NDk4MzkvcmVzb3VyY2VzIiwiY2xpZW50X2lkIjoiOWY1OTdiMGItYmE2NC00MWI4LWJlNmUtYWViN2QyZTc5NmZjIiwic3ViIjoiMmYzYjFhODAtMmE4OS00MjhmLTgwYmUtMmE4NmI2YTk3Mjk5IiwiYXV0aF90aW1lIjoiNjM2NDY4OTU5MTk5MTI1NjY5IiwiaWRwIjoiaHR0cHM6Ly9sb2dpbi53aW5kb3dzLm5ldCIsInByZWZlcnJlZF91c2VybmFtZSI6IlRlc3QgUmV2aWV3ZXIgMSIsIm5hbWUiOiJ0ZWNoMUBlcGljc2NpZW5jZXMuY29tIiwiZW1haWwiOiIiLCJyb2xlIjpbIlNURyIsIlJldmlld2VyIiwiREVWIiwiU1FFIl0sImp0aSI6IjEyMTFlOGQzOTBhM2RmNmI5NmJhNDcyMDI2OWJjMzljIiwic2NvcGUiOlsiZW1haWwiLCJvcGVuaWQiLCJwcm9maWxlIiwicm91dGVyLmZ1bGxfYWNjZXNzIiwib2ZmbGluZV9hY2Nlc3MiXSwiYW1yIjpbInBhc3N3b3JkIl19.X5YN9qqHw8-PvXNLIICbhRExym2ifoGhxS9hh1dxKsek97LM96L_XUVJxhuJ-D6cwXF0JUmMfhAK7KyjMo2LK4IZeEl18TEIOJQbk__0kE2IY4hOLbuV8MNqiz5Xkwsxd0l0349f5yZ5UAZ8rVlT6FEgVSor4b95tq90ZK8C3QtinfYjBDfE54o90LY8_tqSreFa_wiSbCiSbuKxA8R1UY-yCnbO4UvrPapTgGQvGGQcNDG1fj3MNNV1g_ghJwV_KGRddiAYSlI3Vt6UHptK39LNkyjSV4X1alfoNup_kFOnMdXDtT54fPq6-2SWDtb0w6DMIVb1HI2zYnZj6uZmfEdkvdj6RAvtZ8o_8K0D-1GKDpbnTv0s3qWJWH86zUmLISvHhuayOUKHHlhdamB8A4WrxlrM-bL6ixaX9cQ3DTcHFdHm81cIuvcur9Ql_jWvHhKnvWGNqTHBKMOUg43X4nQqBqJnUu04sCAQCrFKJmqa3rEytP1fLjI-6HjlIqdqy3ggTJdmixhTL0xGs6raGh9vlT509w1fZxtmmj9E6FDBdLOsk7GleKAUkRL1CkOJ46fa5yMMD1mSjs3jllgMNTPtt46DtI91iHDN8X6KFhi6dEoesogigI5FNL7tTkqJ1TmtnHlWZs6QqSYh8e4Wp5TWEaGD5mHOQUK3bn2S54Y 2017-11-21 13:18:40.472 -08:00 [DBG] Token request success. 2017-11-21 13:18:40.473 -08:00 [VRB] Invoking result: IdentityServer4.Endpoints.Results.TokenResult 2017-11-21 13:18:40.512 -08:00 [DBG] Connection id "0HL9H4KGL18B0" completed keep alive response. 2017-11-21 13:18:40.512 -08:00 [INF] Request finished in 5689.0343ms 200 application/json 2017-11-21 13:19:13.911 -08:00 [INF] Request starting HTTP/1.1 POST http://localhost:49839/connect/token application/x-www-form-urlencoded 201 2017-11-21 13:19:13.911 -08:00 [DBG] AuthenticationScheme: idsrv was not authenticated. 2017-11-21 13:19:13.911 -08:00 [DBG] Request path /connect/token matched to endpoint type "Token" 2017-11-21 13:19:13.911 -08:00 [DBG] Mapping found for endpoint: "Token", creating handler: IdentityServer4.Endpoints.TokenEndpoint 2017-11-21 13:19:13.912 -08:00 [INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.TokenEndpoint for /connect/token 2017-11-21 13:19:13.912 -08:00 [VRB] Processing token request. 2017-11-21 13:19:13.912 -08:00 [DBG] Start token request. 2017-11-21 13:19:13.912 -08:00 [DBG] Start client validation 2017-11-21 13:19:13.912 -08:00 [DBG] Start parsing Basic Authentication secret 2017-11-21 13:19:13.912 -08:00 [DBG] Start parsing for secret in post body 2017-11-21 13:19:13.916 -08:00 [DBG] Parser found secret: PostBodySecretParser 2017-11-21 13:19:13.917 -08:00 [DBG] Secret id found: 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc 2017-11-21 13:19:13.917 -08:00 [DBG] 9f597b0b-ba64-41b8-be6e-aeb7d2e796fc found in database: true 2017-11-21 13:19:13.917 -08:00 [DBG] Public Client - skipping secret validation success 2017-11-21 13:19:13.917 -08:00 [DBG] Client validation success 2017-11-21 13:19:13.917 -08:00 [DBG] Start token request validation 2017-11-21 13:19:13.922 -08:00 [DBG] Start validation of refresh token request 2017-11-21 13:19:16.053 -08:00 [DBG] e/Dm2lN+CkIGD7Mf6Xge9h6Kno0pdyO2pJLfE7ok6V0= found in database: true 2017-11-21 13:19:26.454 -08:00 [DBG] refresh_token grant with value: fe8dfc8820159e3ec9038cb677094a66df8e09c841458617d54232cf2f4359bd found in store, but has expired. 2017-11-21 13:19:26.455 -08:00 [ERR] Invalid refresh token: fe8dfc8820159e3ec9038cb677094a66df8e09c841458617d54232cf2f4359bd 2017-11-21 13:19:26.455 -08:00 [ERR] { "ClientId": "9f597b0b-ba64-41b8-be6e-aeb7d2e796fc", "GrantType": "refresh_token", "RefreshToken": "fe8dfc8820159e3ec9038cb677094a66df8e09c841458617d54232cf2f4359bd", "Raw": { "grant_type": "refresh_token", "client_id": "9f597b0b-ba64-41b8-be6e-aeb7d2e796fc", "client_secret": "", "refresh_token": "fe8dfc8820159e3ec9038cb677094a66df8e09c841458617d54232cf2f4359bd" } } 2017-11-21 13:19:26.457 -08:00 [VRB] Invoking result: IdentityServer4.Endpoints.Results.TokenErrorResult 2017-11-21 13:19:26.460 -08:00 [DBG] Connection id "0HL9H4KGL18B0" completed keep alive response. 2017-11-21 13:19:26.460 -08:00 [INF] Request finished in 12548.9234ms 400 application/json

LOGS ARE IN PST.

Token expiration in UTC: 2017-11-21T21:18:33.333Z 1511299113

diomedtmc commented 6 years ago

So, when I inspect the code in the debugger the date is of Kind Local. I suspect this is my issue.

diomedtmc commented 6 years ago

See my last comment, this was totally my issue. I was getting "help" from my underlying model mapping layer and all dates were transporting around as "DateTimeKind.Local". Converted the values to Utc after mapping solved my problem.

`
var result = token == null ? null : Mapper.Map(token);

        if(result != null)
        {
            result.CreationTime = result.CreationTime.ToUniversalTime();
            if (result.Expiration.HasValue)
            {
                result.Expiration = result.Expiration.Value.ToUniversalTime();
            }
        }

`

lock[bot] commented 4 years ago

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.