“Provided Authorization Grant is invalid” when using refresh_token WSO2 IS 5.2.0

Question

I recently updated my environment from WSO2 IS 5.0.0 to WSO2 IS 5.2.0. My environment consists of one machine deployed on EC2 AWS instance. I am using MySQL(not the default H2 database). The machine on which the IS is deployed is Windows Server 2012 R2.
I am using the password grant type in order to get access token for particular user and also store the refresh token so that I am able to issue another access token when needed. I am doing the following request in order to get access token:
POST
https://(IS-URL)/oauth2/token?scope=openif&grant_type=password&[email protected]@localhost.io&password=Asd123@@
Configure the appropriate Authorization Basic header
After that I am using the refresh token in order to issue new access tokens. For example:
POST
https://(IS-URL)/oauth2/token?scope=openid&grant_type=refresh_token&refresh_token=
Configure the appropriate Authorization Basic header
After I execute the latest POST call from Postman several times in 2-5 sec interval, after the first 5-7 calls, I start to receive the following error response:

{  
 "error": "invalid_grant",  
 "error_description": "Provided Authorization Grant is invalid"  
}

I am expecting to receive the new access token and instead I am receiving the mentioned above error. Then I modifiedthe log4j.properties by updating the following lines:

log4j.logger.org.wso2.carbon.identity=DEBUG
log4j.logger.org.wso2.carbon.identity.application=DEBUG
log4j.logger.org.wso2.carbon.identity.mgt=DEBUG
log4j.logger.org.wso2.carbon.identity.oauth2=DEBUG
log4j.logger.org.wso2.carbon.identity.provisioning=DEBUG
log4j.logger.org.wso2.carbon.identity.user.account.association=DEBUG
log4j.logger.org.wso2.carbon.identity.user.profile.mgt=DEBUG

Then I started the IS and tried again the mentioned above scenario and this is what I received in the log file:

[2016-11-15 21:29:18,873] DEBUG     {org.wso2.carbon.identity.oauth2.OAuth2Service} -  Access Token request received for Client ID GCFfyPSGkykWG4zQTKoDp8NEvjIa, User ID null, Scope :   [openid] and Grant Type : refresh_token
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.token.handlers.clientauth.AbstractClientAuthHandler} -  Can authenticate with client ID and Secret. Client ID: GCFfyPSGkykWG4zQTKoDp8NEvjIa
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.token.handlers.clientauth.AbstractClientAuthHandler} -  Grant type : refresh_token Strict client validation set to : null
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.util.OAuth2Util} -  Client credentials were available in the cache for client id : GCFfyPSGkykWG4zQTKoDp8NEvjIa
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.util.OAuth2Util} -  Successfully authenticated the client with client id : GCFfyPSGkykWG4zQTKoDp8NEvjIa
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.token.handlers.grant.RefreshGrantHandler} -  Access Token is not in 'ACTIVE' or 'EXPIRED' state for Client with Client Id : GCFfyPSGkykWG4zQTKoDp8NEvjIa
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.token.AccessTokenIssuer} -  Invalid Grant provided by the client Id: GCFfyPSGkykWG4zQTKoDp8NEvjIa
[2016-11-15 21:29:18,873] DEBUG {org.wso2.carbon.identity.oauth2.token.AccessTokenIssuer} -  OAuth-Error-Code=invalid_grant client-id=GCFfyPSGkykWG4zQTKoDp8NEvjIa grant-type=refresh_token scope=openid

For more information, please take a look at the whole log file:
https://www.dropbox.com/s/ygfc9hrrgxjkzkh/console.log?dl=0
Has someone experienced similar issue and could this be bug in the IS or it is caused by some sort of misconfiguration?
I took a look at Refresh token returns invalid grant type but was not able to find direct answer to the question.
Just want to mention that I tried issuing one request per second and tried this for 5 min interval and was not able to reproduce the issue. It seems it happens when the request frequency is high enough.
Thanks in advance.

OAuthProblemException{error='invalid_request', description='Missing parameters: refresh_token', uri='null', state='null', scope='null', redirectUri='null', responseStatus=0, parameters={}} something wrong with the request you send for refresh token? — farasath
I am sending the exact same request and it is okay several times and when the same request is executed within a short time frame (for example 10 requests for 2-5 sec) suddenly it starts to return "error": "invalid_grant". I do not think there is something wrong with the request because it is the same every time. I ma using the following configuration when it comes to refresh token: <RenewRefreshTokenForRefreshGrant>false</RenewRefreshTokenForRefreshGrant> — Mariyan Stefanov

Bee Bee · Accepted Answer · 2016-11-16T17:05:47

As per this code and your logs, the access token is neither in 'ACTIVE' nor 'EXPIRED' state. You can look for that particular token in IDN_OAUTH2_ACCESS_TOKEN table. That will give you a hint about what has gone wrong.

Update: I analyzed your dataset. The problem is that since you have sent the same token request several times, there are many entries in this tables with TOKEN_STATE=INACTIVE. And also you have 2 entries with the same timestamp (i.e. 2016-11-17 11:40:02) in TIME_CREATED column, which has happened to be the latest among all. So when IS tries to pick the latest token (which ideally should be the ACTIVE one) db server returns 2 tokens. But IS has to pick just one. It can be any of those 2 since the timestamp is the same. So when it picks the INACTIVE one, you should see above error.

Ideally, IS should have handled this properly. But as a solution for you, if you do not keep sending the same request very frequently, you should be able to get rid of the error. Just send a request and wait till the response comes. If it takes a lot of time, that's a different issue to analyze and solve.

“Provided Authorization Grant is invalid” when using refresh_token WSO2 IS 5.2.0

1 Answers