"unknown, invalid, or expired refresh token","error":"invalid_grant - Can Apache handle multiple requests from one client in a short time?

[ILoveITScience]

Hi,

I've configured my Apache instance as an RP to connect to an existing OP. Below are my Apache configurations.

An Angular client uses Apache to retrieve the access token every 29 minutes. The Angular client uses the access token to access REST services in the backend. In general it's working. But from time to time (maybe evey 3-4 hours) I get an 401 from the backend.

I found out that Apache does not refresh the access token in that case:

The access token stays the same. I also found some errors in the log

Update: it seems like I get an invalid access token if one client sends two or more request in a very short time (ms) to Apache.

Configuration:

Define SRVROOT "C:/Apache24"
ServerRoot "${SRVROOT}"

Define ENABLE_TLS13 "Yes"

Listen 443

LoadModule actions_module modules/mod_actions.so
LoadModule alias_module modules/mod_alias.so
LoadModule allowmethods_module modules/mod_allowmethods.so
LoadModule asis_module modules/mod_asis.so
LoadModule auth_basic_module modules/mod_auth_basic.so
LoadModule authn_core_module modules/mod_authn_core.so
LoadModule authn_file_module modules/mod_authn_file.so
LoadModule authz_core_module modules/mod_authz_core.so
LoadModule authz_groupfile_module modules/mod_authz_groupfile.so
LoadModule authz_host_module modules/mod_authz_host.so
LoadModule authz_user_module modules/mod_authz_user.so
LoadModule autoindex_module modules/mod_autoindex.so
LoadModule cgi_module modules/mod_cgi.so
LoadModule dir_module modules/mod_dir.so
LoadModule env_module modules/mod_env.so
LoadModule http2_module modules/mod_http2.so
LoadModule include_module modules/mod_include.so
LoadModule info_module modules/mod_info.so
LoadModule isapi_module modules/mod_isapi.so
LoadModule log_config_module modules/mod_log_config.so
LoadModule mime_module modules/mod_mime.so
LoadModule negotiation_module modules/mod_negotiation.so
LoadModule proxy_module modules/mod_proxy.so
LoadModule proxy_http_module modules/mod_proxy_http.so
LoadModule setenvif_module modules/mod_setenvif.so
LoadModule socache_shmcb_module modules/mod_socache_shmcb.so
LoadModule ssl_module modules/mod_ssl.so
LoadModule status_module modules/mod_status.so

<IfModule unixd_module>
User daemon
Group daemon
</IfModule>

ServerAdmin admin@example.com
ServerName localhost:80

<Directory />
    AllowOverride none
    Require all denied
</Directory>

DocumentRoot "${SRVROOT}/htdocs"
<Directory "${SRVROOT}/htdocs">
    Options Indexes FollowSymLinks
    AllowOverride None
    Require all granted
</Directory>

<IfModule dir_module>
    DirectoryIndex index.html
</IfModule>

<Files ".ht*">
    Require all denied
</Files>

ErrorLog "logs/error.log"

LogLevel warn

<IfModule log_config_module>
    LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
    LogFormat "%h %l %u %t \"%r\" %>s %b" common

    <IfModule logio_module>

      LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O" combinedio
    </IfModule>

    CustomLog "logs/access.log" common
</IfModule>

<IfModule alias_module>
    ScriptAlias /cgi-bin/ "${SRVROOT}/cgi-bin/"
</IfModule>

<IfModule cgid_module>
</IfModule>

<Directory "${SRVROOT}/cgi-bin">
    AllowOverride None
    Options None
    Require all granted
</Directory>

<IfModule mime_module>
    TypesConfig conf/mime.types
    AddType application/x-compress .Z
    AddType application/x-gzip .gz .tgz
</IfModule>

Include conf/extra/httpd-autoindex.conf
Include conf/extra/httpd-info.conf

<IfModule proxy_html_module>
Include conf/extra/httpd-proxy-html.conf
</IfModule>

<IfModule ssl_module>
SSLRandomSeed startup builtin
SSLRandomSeed connect builtin
</IfModule>

<IfModule http2_module>
    ProtocolsHonorOrder On
    Protocols h2 h2c http/1.1
</IfModule>

<IfModule lua_module>
  AddHandler lua-script .lua
</IfModule>

<VirtualHost _default_:443>

  SSLEngine on
  SSLProxyEngine on
  SSLCertificateFile "C:\Apache24\conf\ssl\xxx.crt"
  SSLCertificateKeyFile "C:\Apache24\conf\ssl\sgagawvidfl2.key"
  SSLCertificateChainFile "C:\Apache24\conf\ssl\cert-chain.crt"
  
  OIDCSSLValidateServer Off
  OIDCScope "openid email profile organizational_data personal_data com_data offline_access"
  OIDCProviderMetadataURL https://sso-xxx/openid-configuration

  OIDCClientID xxx
  OIDCClientSecret xxx

  OIDCCryptoPassphrase <password>

  OIDCRedirectURI /auth

  OIDCResponseType "code"
  
  OIDCInfoHook userinfo
  OIDCInfoHook access_token
  OIDCInfoHook iat
  OIDCInfoHook access_token_expires
  OIDCInfoHook id_token
  OIDCInfoHook refresh_token
  OIDCInfoHook session
  OIDCSessionInactivityTimeout 28800
  OIDCUserInfoRefreshInterval 500
  OIDCRefreshAccessTokenBeforeExpiry 600

#  <Location "/auth">
#    AuthType openid-connect
#	Require valid-user
#	LogLevel warn
#  </Location>

  <Location "/">
    AuthType openid-connect
	Require valid-user
	LogLevel debug
    #Require claim sub:<userid>
  </Location>

  Redirect /XX /

  ProxyPass /XX !
  ProxyPass /auth !  
  
  ProxyPass /felogging https://xxx:8087/
  ProxyPassReverse /felogging https://xxx:8087/

  ProxyPass / http://yyy:755/
  ProxyPassReverse / http://yyy:755/
</VirtualHost>

Logs:

[Wed Apr 14 12:45:52.555000 2021] [ssl:debug] [pid 8184:tid 1148] ssl_engine_kernel.c(1741): [rem xx-xxx-xx-yyote  xx-xxx-xx-yy:8085] AH02275: Certificate Verification, depth 1, CRL checking mode: none (0) [subject: xxx / notbefore: Nov  2 14:39:32 2016 GMT / notafter: Nov  2 14:49:32 2026 GMT]
[Wed Apr 14 12:45:52.556001 2021] [ssl:debug] [pid 8184:tid 1148] ssl_engine_kernel.c(1741): [remote  xx-xxx-xx-yy:8085] AH02275: Certificate Verification, depth 0, CRL checking mode: none (0) [subject: xxx / notbefore: Sep  3 07:41:36 2020 GMT / notafter: Sep  3 07:41:36 2022 GMT]
[Wed Apr 14 12:45:52.560001 2021] [ssl:debug] [pid 8184:tid 1148] ssl_engine_kernel.c(2231): [remote  xx-xxx-xx-yy:8085] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
[Wed Apr 14 12:45:52.561001 2021] [ssl:debug] [pid 8184:tid 1148] ssl_util_ssl.c(476): AH02412: [my-url:443] Cert matches for name 'myserver' [subject: xxx / notbefore: Sep  3 07:41:36 2020 GMT / notafter: Sep  3 07:41:36 2022 GMT]
[Wed Apr 14 12:45:52.566001 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(825): [client xx-xxx-xx-xx:59951] oidc_util_http_call: HTTP response code=200, referer: https://my-url/
[Wed Apr 14 12:45:52.566001 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(830): [client xx-xxx-xx-xx:59951] oidc_util_http_call: response={"access_token":"00017zmAZpHhqBvuUsrNXCUA4J4X","refresh_token":"bYlmQY156kYC1vHPU7eC9bkJvgCrNCHvZemh0Y0aNA","token_type":"Bearer","expires_in":1799}, referer: 
[Wed Apr 14 12:45:52.567002 2021] [auth_openidc:debug] [pid 8184:tid 1156] util.c(825): [client xx-xxx-xx-xx:59955] oidc_util_http_call: HTTP response code=400, referer: https://my-url/
[Wed Apr 14 12:45:52.567002 2021] [auth_openidc:debug] [pid 8184:tid 1156] util.c(830): [client xx-xxx-xx-xx:59955] oidc_util_http_call: response={"error_description":"unknown, invalid, or expired refresh token","error":"invalid_grant"}, referer: https://my-url/
[Wed Apr 14 12:45:52.567002 2021] [auth_openidc:error] [pid 8184:tid 1156] [client xx-xxx-xx-xx:59955] oidc_util_json_string_print: oidc_util_check_json_error: response contained an "error" entry with value: ""invalid_grant"", referer: https://my-url/
[Wed Apr 14 12:45:52.567002 2021] [auth_openidc:error] [pid 8184:tid 1156] [client xx-xxx-xx-xx:59955] oidc_util_json_string_print: oidc_util_check_json_error: response contained an "error_description" entry with value: ""unknown, invalid, or expired refresh token"", referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:error] [pid 8184:tid 1156] [client xx-xxx-xx-xx:59955] oidc_refresh_access_token: access_token could not be refreshed, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:warn] [pid 8184:tid 1156] [client xx-xxx-xx-xx:59955] oidc_handle_info_request: access_token could not be refreshed, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] mod_auth_openidc.c(1132): [client xx-xxx-xx-xx:59955] oidc_get_provider_from_session: enter, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] common.c(569): [client xx-xxx-xx-xx:59955] oidc_cache_get: enter: https://sso xxx openid-configuration (section=p, decrypt=0, type=shm), referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] common.c(603): [client xx-xxx-xx-xx:59955] oidc_cache_get: cache hit: return 1408 bytes from shm cache backend for key https://sso xxx openid-configuration, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] mod_auth_openidc.c(1346): [client xx-xxx-xx-xx:59955] oidc_refresh_claims_from_userinfo_endpoint: userinfo_endpoint=https://sso xxx userinfo.openid, interval=0, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] util.c(2289): [client xx-xxx-xx-xx:59955] oidc_util_hdr_table_set: OIDC_access_token: 0001mz3XQNCD9hB0I5W5bL7weB2k, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] util.c(1708): [client xx-xxx-xx-xx:59955] oidc_util_set_app_info: setting environment variable "OIDC_access_token: 0001mz3XQNCD9hB0I5W5bL7weB2k", referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] util.c(2289): [client xx-xxx-xx-xx:59955] oidc_util_hdr_table_set: OIDC_access_token_expires: 1618398951, referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] util.c(1708): [client xx-xxx-xx-xx:59955] oidc_util_set_app_info: setting environment variable "OIDC_access_token_expires: 1618398951", referer: https://my-url/
[Wed Apr 14 12:45:52.568001 2021] [auth_openidc:debug] [pid 8184:tid 1156] mod_auth_openidc.c(1012): [client xx-xxx-xx-xx:59955] oidc_log_session_expires: session inactivity timeout: Wed, 14 Apr 2021 18:45:50 GMT (in 28797 secs from now), referer: https://my-url/
[Wed Apr 14 12:45:52.569004 2021] [auth_openidc:debug] [pid 8184:tid 1136] mod_auth_openidc.c(1132): [client xx-xxx-xx-xx:59951] oidc_get_provider_from_session: enter, referer: https://my-url/
[Wed Apr 14 12:45:52.569004 2021] [auth_openidc:debug] [pid 8184:tid 1136] common.c(569): [client xx-xxx-xx-xx:59951] oidc_cache_get: enter: https://sso xxx openid-configuration (section=p, decrypt=0, type=shm), referer: https://my-url/
[Wed Apr 14 12:45:52.569004 2021] [auth_openidc:debug] [pid 8184:tid 1136] common.c(603): [client xx-xxx-xx-xx:59951] oidc_cache_get: cache hit: return 1408 bytes from shm cache backend for key https://sso xxx openid-configuration, referer: https://my-url/
[Wed Apr 14 12:45:52.569004 2021] [auth_openidc:debug] [pid 8184:tid 1136] mod_auth_openidc.c(1346): [client xx-xxx-xx-xx:59951] oidc_refresh_claims_from_userinfo_endpoint: userinfo_endpoint=https://sso xxx userinfo.openid, interval=0, referer: https://my-url/
[Wed Apr 14 12:45:52.569004 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(2289): [client xx-xxx-xx-xx:59951] oidc_util_hdr_table_set: OIDC_access_token: 00017zmAZpHhqBvuUsrNXCUA4J4X, referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(1708): [client xx-xxx-xx-xx:59951] oidc_util_set_app_info: setting environment variable "OIDC_access_token: 00017zmAZpHhqBvuUsrNXCUA4J4X", referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(2289): [client xx-xxx-xx-xx:59951] oidc_util_hdr_table_set: OIDC_access_token_expires: 1618398951, referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(1708): [client xx-xxx-xx-xx:59951] oidc_util_set_app_info: setting environment variable "OIDC_access_token_expires: 1618398951", referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] mod_auth_openidc.c(1012): [client xx-xxx-xx-xx:59951] oidc_log_session_expires: session inactivity timeout: Wed, 14 Apr 2021 18:45:50 GMT (in 28797 secs from now), referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] common.c(628): [client xx-xxx-xx-xx:59951] oidc_cache_set: enter: 422fda63-c34f-714a-958d-0ef277f69835 (section=s, len=5572, encrypt=0, ttl(s)=28797, type=shm), referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] common.c(655): [client xx-xxx-xx-xx:59951] oidc_cache_set: successfully stored 5572 bytes in shm cache backend for key 422fda63-c34f-714a-958d-0ef277f69835, referer: https://my-url/
[Wed Apr 14 12:45:52.570001 2021] [auth_openidc:debug] [pid 8184:tid 1136] util.c(2311): [client xx-xxx-xx-xx:59951] oidc_util_hdr_err_out_add: Set-Cookie: mod_auth_openidc_session=422fda63-c34f-714a-958d-0ef277f69835; Path=/; Secure; HttpOnly, referer: https://my-url/
[Wed Apr 14 12:45:52.578002 2021] [proxy:debug] [pid 8184:tid 1144] proxy_util.c(2340): AH00943: https: has released connection for (myserver)
[Wed Apr 14 12:45:52.578002 2021] [proxy:debug] [pid 8184:tid 1140] proxy_util.c(2340): AH00943: https: has released connection for (myserver)
[Wed Apr 14 12:45:52.581003 2021] [proxy:debug] [pid 8184:tid 1148] proxy_util.c(2340): AH00943: https: has released connection for (myserver)
[Wed Apr 14 12:45:52.639006 2021] [ssl:debug] [pid 8184:tid 1148] ssl_engine_kernel.c(376): [client xx-xxx-xx-xx:59952] AH02034: Subsequent (No.3) HTTPS request received for child 52 (server my-url:443), referer: https://my-url/
[Wed Apr 14 12:45:52.639006 2021] [authz_core:debug] [pid 8184:tid 1148] mod_authz_core.c(817): [client xx-xxx-xx-xx:59952] AH01626: authorization result of Require valid-user : denied (no authenticated user yet), referer: https://my-url/
[Wed Apr 14 12:45:52.640010 2021] [authz_core:debug] [pid 8184:tid 1148] mod_authz_core.c(817): [client xx-xxx-xx-xx:59952] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet), referer: https://my-url/
[Wed Apr 14 12:45:52.640010 2021] [auth_openidc:debug] [pid 8184:tid 1148] mod_auth_openidc.c(3763): [client xx-xxx-xx-xx:59952] oidc_check_user_id: incoming request: "/18.f6eece663e9eb3e87189.js?(null)", ap_is_initial_req(r)=1, referer: https://my-url/
[Wed Apr 14 12:45:52.640010 2021] [auth_openidc:debug] [pid 8184:tid 1148] util.c(2233): [client xx-xxx-xx-xx:59952] oidc_util_hdr_in_get: Host=my-url, referer: https://my-url/
[Wed Apr 14 12:45:52.640010 2021] [auth_openidc:debug] [pid 8184:tid 1148] util.c(2233): [client xx-xxx-xx-xx:59952] oidc_util_hdr_in_get: Host=my-url, referer: https://my-url/

From my Angular application I call Apache with the following link to retrieve the access token
const userInfoUrl = '/auth?info=json';
also tried
const tokenRefreshUrl = '/auth?info=json&access_token_refresh_interval=60';
and
const tokenRefreshUrl = '/auth?info=json&access_token_refresh_interval=0';

Apache Version: 2.4.47

[zandbelt]

I believe that is a problem indeed: when the Authorization Server uses rolling refresh tokens and there's 2 parallel requests coming in from the same client that both decide the access token needs to be refreshed, only one can/will win. It is hard to protect 100% against this in code though I will think more about pushing down the odds a bit. For the time being, a potential workaround is to have the server not issue a new refresh token on each token request or to try and avoid having the client issue parallel refresh requests.

[ILoveITScience]

Now we call Apache only once every half an hour. The Apache logs confirm this.

But today we still got the error. Is the general approach correct? => An Angular client uses Apache ( '/auth?info=json';) to retrieve the access token every 29 minutes. The Angular client uses then the access token to access REST services in the backend (set it into the header) and then request to /myEndpoint.

ATM we have no idea how to deal with this error. Most of the time its working fine.

[zandbelt]

a mitigation for this issue is now in place in https://github.com/OpenIDC/mod_auth_openidc/releases/tag/v2.4.15.3