refresh token routine called but existing parallel refresh is in progress

[esunke]

Hi, I am using mod_auth_openidc to authenticate with keycloak 21.1.2.
I updated the the latest versions of:

• liboauth2_1.5.1-2.focal_amd64.deb
• liboauth2-apache_1.5.1-2.focal_amd64.deb
• libapache2-mod-auth-openidc_2.4.14.4-1.focal_amd64.deb
• libapache2-mod-oauth2_3.3.1-2.focal_amd64.deb

Now I am not able to refresh tokens any more. I keep getting "refresh token routine called but existing parallel refresh is in progress" and "access_token could not be refreshed" in the apache error log and since the token cannot be refreshed, I am logged out again.
Besides the refresh token issue, authentication works well in my setup.

I started my issuejourney with not encrypting the shm cache. However I recieved the message that the token cannot be cached because of the size. Same happens with file based cache. file to large. The issue is that the complete jwt seems to be the key.
I found some blogs about fixing this by encrypting the cache. That worked to get rid of the error messages about the cache. Now I am facing the issue with the refresh token.

Is there something I am missing?

With the older following versions I did not have these issues:

• libapache2-mod-auth-openidc_2.4.10-1.focal+1_amd64.deb
• liboauth2_1.4.4.1-1.focal+1_amd64.deb
• libapache2-mod-oauth2_3.2.2-1.focal+1_amd64.deb

[zandbelt]

I'd need to see the server debug logs and the config to be able to analyze why the refresh is in progress

[esunke]

Hi @zandbelt,
thanks for the quick reply. I will try to provide the debug logs. Until then, what I have found out is that I changed the configuration from
"OIDCRefreshAccessTokenBeforeExpiry 10 logout_on_error"
to
"OIDCRefreshAccessTokenBeforeExpiry 10"

And now there is no log entries any more and the session cookie gets refreshed as expected.
In the release notes of 2.4.14.4 I saw a comment about a fix for thsi parameter: https://github.com/OpenIDC/mod_auth_openidc/releases/tag/v2.4.14.4
Maybe this is related?

Best regrads,
Eik

[zandbelt]

I see, thanks: special handling for the "logout_on_error" case would be more appropriate indeed, something we'll add in the next release

[esunke]

Hi Hans,
Even without the "logout_on_error" parameter, I now saw the following lines in the regular log after doing some further testing:

[Wed Oct 25 09:48:27.679081 2023] [auth_openidc:warn] [pid 11:tid 139725008529152] [client :49444] oidc_refresh_token_grant: refresh token routine called but existing parallel refresh is in progress, referer: https://.../index.html?force=18b659fd5d3
[Wed Oct 25 09:48:27.679109 2023] [auth_openidc:warn] [pid 11:tid 139725008529152] [client 1:49444] oidc_refresh_access_token_before_expiry: access_token could not be refreshed, referer: https://.../index.html?force=18b659fd5d3
[Wed Oct 25 09:58:27.765088 2023] [auth_openidc:warn] [pid 10:tid 139725931267840] [client 1:57618] oidc_refresh_token_grant: refresh token routine called but existing parallel refresh is in progress, referer: https://.../index.html?force=18b659fd5d3
[Wed Oct 25 09:58:27.765115 2023] [auth_openidc:warn] [pid 10:tid 139725931267840] [client 1:57618] oidc_refresh_access_token_before_expiry: access_token could not be refreshed, referer: https://.../ticker/index.html?force=18b659fd5d3
[Wed Oct 25 10:04:10.172218 2023] [auth_openidc:error] [pid 10:tid 139724966565632] [client 1:36830] oidc_restore_proto_state: state has expired
[Wed Oct 25 10:04:10.172241 2023] [auth_openidc:error] [pid 10:tid 139724966565632] [client 1:36830] oidc_authorization_response_match_state: unable to restore state

The only difference was / is that I was using two different user and the keycloak showed the session of the user (with the error) as active.
For me this looks like a scenario where The session is not cleaned up from keycloak and when I reauthenticate, the session cannot be refreshed from. Could that be?

[esunke]

One more thing I saw:
I am using Browser A on system A and login. Then I am using browser b on system b and also login. I see both sessions in Keycloak. However, after a while I start seeing the refresh errors in the log file. Now when I logout from Browser A, Browser B has a very strange state. It still thinks that it is logeed in but when accessing auth resources (for example: /realms/${REALM}/protocol/openid-connect/userinfo) It is not authenticated. This also goes in the direction that the sessions are not sepeareted as they should be.

[zandbelt]

both sessions are most probably receiving the same refresh token and both will be trying to refresh this at the same time which will indeed leave things in an unpredictable state; we'll add a feature that allows for backwards compatibility i.e. allowing for logout on any type of error, including parallel refreshs

[esunke]

OK. Until then, what do you think is the best version to use? The ones I used before?

[zandbelt]

sure

[studersi]

We recently upgraded to mod_auth_openidc 2.4.14.4 and are seeing similar errors on a number of services where OIDCRefreshAccessTokenBeforeExpiry is used. We are still investigating, where and why this error occurs, and what the impact is.

I am not sure I understand the issue exactly. Is a user not allowed to be logged-in in multiple, separate browsers as described here: #1132 (reply in thread)? To me, this seems like a very common use-case, one we see frequently.

Are there other situations, where this error is likely to happen?

Is this error caused by a bug in mod_auth_openidc or by a mishandling of access tokens by the IDP?

The options logout_on_error and authenticate_on_error are not really viable workarounds in many cases since we actually need the access token to be refreshed instead. Using these flags would mean very frequent but mostly transparent login redirects in the very best case. In the worst case, this would mean broken single-page applications where the user sees generic errors. Either way, users would be interrupted in whatever they were doing (forms and other input fields cleared etc.).

---

Here an example from our error log, the response status was 401:

[2023-12-05 06:59:07.132658] [auth_openidc:warn] WWW.XXX.YYY.ZZZ:62347 WOEIURWOEUUZROWRWO oidc_refresh_access_token_before_expiry: access_token could not be refreshed
[2023-12-05 06:59:07.132604] [auth_openidc:warn] WWW.XXX.YYY.ZZZ:62347 WOEIURWOEUUZROWRWO oidc_refresh_token_grant: refresh token routine called but existing parallel refresh

[zandbelt]

in all cases this does not prevent users from being logged in to two different clients/browsers necessarily but the issue appears when refreshing an access token on >1 parallel calls/servers/browsers and a new refresh token is issued in each parallel request

the issue is flagged by mod_auth_openidc since it started to detect and handle this case in a different way: I wouldn't go as far as calling it a bug though since realistically you cannot expect this scenario (parallel refresh) to work in a distributed environment when combined with rolling refresh tokens; however the upcoming release will revert the behaviour as it was before

for now I'd stick with an earlier release even though you would end up with different refresh tokens in the 2 clients and one of them should/would not work...; the more deterministic approach (in both cases) is to not renew the refresh token on each access token refresh request

[zandbelt]

update: @studersi well actually a bug does apply here since it appears that 2.4.14.4 does not differentiate between rolling refresh tokens and non-rolling refresh token cases, so indeed the upcoming release will fix that bug by reverting to the previous behaviour which works fine with (largely) static refresh tokens whilst providing an optionally configured improvement for the rolling refresh token use case

[studersi]

@zandbelt Thank you for the quick analysis! We ended up rolling back to a previous version to solve the issue and will try the fixed version when it is released.

[zandbelt]

this is now in 2.4.15 https://github.com/OpenIDC/mod_auth_openidc/releases/tag/v2.4.15

[zandbelt]

proper mitigation for parallel refreshes is now in https://github.com/OpenIDC/mod_auth_openidc/releases/tag/v2.4.15.3