Handling token expiry

[evilfer]

Hi,

I have an Apache 2.4.38 server with mod_auth_openidc 2.3.10, connected with a Keycloak auth server.

Everything seems to be working fine, but we get random errors on logged in sessions. In one browser that was previously today logged in with the server, now trying to reload an authenticated path returns this content:

OpenID Connect Provider error: Error in handling response type.

Looking at the Apache log, the request triggers this error:

[auth_openidc:error] [pid 27] [client 172.18.0.5:54926] oidc_proto_validate_exp: "exp" validation failure (1617198817): JWT expired 21017 seconds ago

There are a couple of redirects, and the server finally responds with 200 and the text above.

I would expect that the openid auth module either refreshes the access token, or that's not possible, redirects the user to the login screen. However, the way it's working right now the user cannot do anything without removing the site cookies.

Could someone please help with the configuration of mod_auth_openidc in Apache or Keycloak to avoid this error?

Thanks,
Eloy

[zandbelt]

it is hard to tell without having the full server debug logs; however, it may be that you're using an older version of Keycloak that re-sends the id_token that was generated before, instead of creating a new one

[evilfer]

Thank you for the quick response :).

Keycloak is jboss/keycloak:11.0.2 (docker image), so seven months ago. There's a newer 11.0.4, and then it's 12; I'm not sure its' possible to upgrade from 11 to 12 by simply replacing the image.

The Apache log is:

172.18.0.5 - - [31/Mar/2021:20:00:20 +0000] "GET / HTTP/1.1" 302 1626 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36"
[Wed Mar 31 20:00:21.301927 2021] [auth_openidc:error] [pid 32] [client 172.18.0.5:55216] oidc_proto_validate_exp: "exp" validation failure (1617198817): JWT expired 22004 seconds ago
[Wed Mar 31 20:00:21.301964 2021] [auth_openidc:error] [pid 32] [client 172.18.0.5:55216] oidc_proto_parse_idtoken: id_token payload could not be validated, aborting
172.18.0.5 - - [31/Mar/2021:20:00:21 +0000] "GET /keycloak/redirect_uri?state=kOoJrtJtNRQ_2NJtHTTAklLG4Xt&session_state=82dbe76c-57c5-41c0-8a8e-ad62038c5b64&code=278124af-bbf4-4a7c-9439-864d0a898b21.82dbe76c-57c5-41c0-8a8e-ad62038c5b63.98bda4a6-a66c-435a-aab6-cfa309bd1827 HTTP/1.1" 200 599 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36"
172.18.0.5 - - [31/Mar/2021:20:00:21 +0000] "GET /favicon.ico HTTP/1.1" 302 1646 "https://smpkh.icr.ac.uk/keycloak/redirect_uri?state=kOoJrtJtNRQ_2NJtHTTAklLG4Xt&session_state=82dbe76c-57c5-41c0-8a8e-ad62038c5b64&code=278124af-bbf4-4a7c-9439-864d0a898b21.82dbe76c-57c5-41c0-8a8e-ad62038c5b63.98bda4a6-a66c-435a-aab6-cfa309bd1827" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36"
[Wed Mar 31 20:00:22.198336 2021] [auth_openidc:error] [pid 23] [client 172.18.0.5:55224] oidc_proto_validate_exp: "exp" validation failure (1617198817): JWT expired 22005 seconds ago
[Wed Mar 31 20:00:22.198372 2021] [auth_openidc:error] [pid 23] [client 172.18.0.5:55224] oidc_proto_parse_idtoken: id_token payload could not be validated, aborting
172.18.0.5 - - [31/Mar/2021:20:00:22 +0000] "GET /keycloak/redirect_uri?state=tc3BG4vZWH1mLk6_fMvsdQzqWOp&session_state=82dbe76c-57c5-41c0-8a8e-ad62038c5b64&code=68dfa16d-8b1e-4890-b542-3e38abb86c19.82dbe76c-57c5-41c0-8a8e-ad62038c5b63.98bda4a6-a66c-435a-aab6-cfa309bd1827 HTTP/1.1" 200 599 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/89.0.4389.90 Safari/537.36"

(not actual tokens/codes, just in case!)

[zandbelt]

that's - by far - not enough to analyze; you should be looking for the id_token that was passed in the first round trip, and see if it's the same the second time around; the keycloak version should be ok

[evilfer]

Sorry I'm not sure where to look for the id_token in the first round trip. That's all the log from an attempt to load the website on the browser with the cookies. In the browser network log, the id_token is not sent to the client, only session cookies.

When logging in to the server for the first time, I can't see the id_token either in the log.

Basically, with every request the session_state and code in the log is always the same (has been for some hours now).