Intermittent CODE_TO_TOKEN_ERROR hitting server behind an AWS ALB

Question

Configuration:

• Node.js Express server sitting behind an AWS ALB with certain routes protected using keycloak-connect (Keycloak Node.js adapter)

• The Express servers are running in a Kubernetes (EKS) cluster with two nodes

• The OIDC client (named 'camp') is access type = confidential

My server serves some static Web pages and a GraphQL API. Certain Web pages need to be protected which I do like so:

keycloak = new Keycloak({cookies: true}, kcConfig);

app.get('/my/web/page', keycloak.protect('admin'), (req, res, next) => {
  next('route'); 
});

This code should check that the authenticated user has the admin role and then pass control to the static web page at /my/web/page.

When I initially hit that route, I am correctly redirected to the Keycloak login page. However, after authenticating I get a 403. In my application log, I see the message: "Could not obtain grant code: Error: 400:Bad Request"

In the Keycloak log, I see:

16:23:28,651 INFO [org.keycloak.events] (default task-428) type=LOGIN, realmId=37b0f797-510c-4e7b-915e-b7e21ea715f8, clientId=camp, userId=***, ipAddress=[ip of browser], auth_method=openid-connect, auth_type=code, response_type=code, redirect_uri=https://***/my/web/page/?auth_callback=1, consent=no_consent_required, code_id=1a559718-1fd6-4b28-8088-aec7c58fc19a, username=***, response_mode=query, authSessionParentId=1a559718-1fd6-4b28-8088-aec7c58fc19a, authSessionTabId=zBPRbp4QclI

16:23:28,710 WARN [org.keycloak.events] (default task-428) type=CODE_TO_TOKEN_ERROR, realmId=37b0f797-510c-4e7b-915e-b7e21ea715f8, clientId=camp, userId=***, ipAddress=[ip of server], error=invalid_code, grant_type=authorization_code, code_id=1a559718-1fd6-4b28-8088-aec7c58fc19a, client_auth_method=client-secret

After waiting a short time or appending some bogus query parameters to the URL or adding a trailing backslash (I'm not sure that any of those things actually "fixes" the problem), I eventually access the Web page successfully without being challenged to authenticate again. I noticed the following in my Keycloak log when I finally successfully get to the Web page:

16:23:46,784 INFO [org.keycloak.events] (default task-428) type=CODE_TO_TOKEN, realmId=37b0f797-510c-4e7b-915e-b7e21ea715f8, clientId=camp, userId=***, ipAddress=[ip of server], token_id=ba9745a2-9884-42b3-97cc-d1e425e552dd, grant_type=authorization_code, refresh_token_type=Refresh, scope='openid profile email roles', refresh_token_id=5d00ead5-8764-4d6a-a0f1-71161efc3360, code_id=1a559718-1fd6-4b28-8088-aec7c58fc19a, client_auth_method=client-secret

Note that this log entry is for a Refresh. I'm not really sure why the initial auth request fails, but finally succeeds with a refresh request. It looks like the initial authentication request succeeds, but fails when getting the access token. But then the request to refresh the access token succeeds?

There's clearly something I don't understand here.

Answer 1

The problem was that I was still using a MemoryStore (the default for express-session) from before I deployed this to a cluster. Guess I need to read my own code a bit more closely. I switched to a database-backed session store and everything works fine now.