IdentityServer3, Azure, and the invalid grant

TL; DR; IdentityServer hosted in Azure and automatic scaling doesn’t work without the creation of an backend storage

While maintaining a previous installation of IdentityServer3 we got some strange errors reported from the web developers. On the web site, that is hosted on EPI server, they got the error when they validated the token.

Server Error in '/' Application.
invalid_grant

Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.

Exception Details: System.Exception: invalid_grant

Source Error:

Line 110: }
 Line 111:
 Line 112: var userInfoClient = new UserInfoClient(
 Line 113: new Uri(AUTHORITY + "/connect/userinfo"),
 Line 114: tokenResponse.AccessToken);

They also reported that if they redirected their development environment towards our acceptance/staging environment, they experienced the problem 90 out of 100 times. But, when they redirected it to our test environment they never saw the problems.

Trying to narrow the problem down we tried to login to the system using different users. We experienced the problem most of the times, but we couldn’t find a pattern. But we found out that if you refresh the page (F5) a couple of times when you get the error, login is successful after a few tries.

So, further, in trying to narrow the error we made sure that test and acceptance hade the same code and configuration. They did. We looked at the certificate that IdentityServer3 used. It where valid for another couple of years. We made sure that the redirect URI didn’t have any trading slashes. No luck.

On to looking at the logs in Azure and Application Insights. And here we see something.

2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.765 +00:00 [Information] Start token request
2016-09-20T14:47:21  PID[76] Verbose     2016-09-20 14:47:21.796 +00:00 [Debug] Start client validation
2016-09-20T14:47:21  PID[76] Verbose     2016-09-20 14:47:21.796 +00:00 [Debug] Start parsing Basic Authentication secret
2016-09-20T14:47:21  PID[76] Verbose     2016-09-20 14:47:21.796 +00:00 [Debug] Parser found secret: "BasicAuthenticationSecretParser"
2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.796 +00:00 [Information] Secret id found: "web"
2016-09-20T14:47:21  PID[76] Verbose     2016-09-20 14:47:21.796 +00:00 [Debug] Secret validator success: "HashedSharedSecretValidator"
2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.796 +00:00 [Information] Client validation success
2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.796 +00:00 [Information] Start token request validation
2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.796 +00:00 [Information] Start validation of authorization code token request
2016-09-20T14:47:21  PID[76] Error       2016-09-20 14:47:21.796 +00:00 [Error] Invalid authorization code: 48b5eb90e8b...979f67
{
  "ClientId": "web",
  "GrantType": "authorization_code",
  "AuthorizationCode": "48b5eb90e8b...979f67",
  "Raw": {
    "grant_type": "authorization_code",
    "code": "48b5eb90e8b...979f67",
    "redirect_uri": "http://URL.com/"
  }
}
2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.796 +00:00 [Information] End token request
2016-09-20T14:47:21  PID[76] Information 2016-09-20 14:47:21.796 +00:00 [Information] Returning error: invalid_grant

Oh, a lead! Invalid authorization code.

Ok. I really don’t know what to do now, but let’s try and hit F5 a couple of times. After three (can sometimes be more and sometimes less…) times the page loads properly. Looking at the logs I see that it parsed the token successfully.

2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.618 +00:00 [Information] Start token request
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.665 +00:00 [Debug] Start client validation
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.665 +00:00 [Debug] Start parsing Basic Authentication secret
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.665 +00:00 [Debug] Parser found secret: "BasicAuthenticationSecretParser"
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Secret id found: "web"
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.665 +00:00 [Debug] Secret validator success: "HashedSharedSecretValidator"
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Client validation success
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Start token request validation
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Start validation of authorization code token request
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Validation of authorization code token request success
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Token request validation success
{
  "ClientId": "web",
  "GrantType": "authorization_code",
  "AuthorizationCode": "48b5eb90e8b...979f67",
  "Raw": {
    "grant_type": "authorization_code",
    "code": "48b5eb90e8b...979f67",
    "redirect_uri": "http://URL.com/"
  }
}
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Creating token response
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.665 +00:00 [Information] Processing authorization code request
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.665 +00:00 [Debug] Creating access token
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.665 +00:00 [Debug] Creating JWT access token
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.682 +00:00 [Debug] Creating identity token
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.682 +00:00 [Information] Getting claims for identity token for subject: f3fae24c-4d77-...-5065f38ada71
2016-09-20T14:47:26  PID[7516] Verbose     2016-09-20 14:47:26.682 +00:00 [Debug] Creating JWT identity token
2016-09-20T14:47:26  PID[7516] Information 2016-09-20 14:47:26.712 +00:00 [Information] End token request

This doesn’t really make any sense. Why would something throw an exception, and if you hit reload a couple of times it works just fine…? Trying to narrow down the error domain further I looked at the authorization code. No luck, it was handled correctly. I looked at the certificate used. Had it expired or something like that. Nope, it looked just fine. Ok, how about the redirect URL and other callback URLs? Some googling reveled that there could be problems with trailing slashes. No luck there either…

Sitting down trying to figure out what changes have I made to the code or the environment in the last couple of weeks. The only thing that I could think of that I haven’t checked yet is my settings in Azure. The IdentityServer is hosted in Azure. I have recently made changes to the app service plan so that it should scale automatically. Let’s try and disable that change. The app service plan should run using only one instance, and it should not scale automatically.

Problem solved! Everything works as expected.

Apparently IdentityServer keeps some kind of state in memory that doesn’t work when scaling on several instances. To handle that you have to build a backend storage solution to distribute authorization codes between processes/instances. That is left as an exercise for the reader…