Behaviour of addAccessTokenExpiring callback changed between 2.4.0 and 3.0.1

[m4rc77]

We have a running application with oidc-client-ts version 2.4.0. We are using automaticSilentRenew: true, accessTokenExpiringNotificationTimeInSeconds: 60 and have registered a callback via addAccessTokenExpiring for logging purposes.

We did a test-update to from 2.4.0 to 3.0.1 and realized a change in behavior.

With 2.4.0:

• Token is going to expire in ~60s
• callback registered via addAccessTokenExpiring is called before the token is refreshed
• The token is silently renewed

With 3.0.1

• Token is going to expire in ~60s
• The token is silently renewed
• callback registered via addAccessTokenExpiring is called after the token is refreshed !?!

Could this be a Bug?

[pamapa]

This MR is touching that area, but i have not seen why that should produce what you see.

Revision: 5af4847a005f5204906ee0946d48656a6da8bba3
Author: pamapa <[email protected]>
Date: 20.12.2023 09:17:04
Message:
fix: #1312 handle promise in Events.raise

----
Modified: docs/oidc-client-ts.api.md
Modified: src/SessionMonitor.ts
Modified: src/SilentRenewService.ts
Modified: src/UserManager.test.ts
Modified: src/UserManager.ts
Modified: src/UserManagerEvents.test.ts
Modified: src/UserManagerEvents.ts
Modified: src/navigators/IFrameWindow.ts
Modified: src/navigators/PopupWindow.ts
Modified: src/utils/Event.test.ts
Modified: src/utils/Event.ts
Modified: src/utils/Timer.test.ts
Modified: src/utils/Timer.ts

and have registered a callback via addAccessTokenExpiring for logging purposes.: Please ensure you register it after the construction of the UserManager, as SilentRenewService is calling addAccessTokenExpiring itself. When adding multiple callbacks, they are handled one by one and called in that sequence. I guess it would be better when you enable logging and set the level to Debug...

[m4rc77]

@pamapa I simplified the code as follows in order to try to track down the issue.

      const manager = new UserManager({
        ...
        accessTokenExpiringNotificationTimeInSeconds: 90,
        automaticSilentRenew: true,
        filterProtocolClaims: false,
        mergeClaims: true,
        response_type: 'code',
        userStore: new WebStorageStateStore({ store: window.localStorage }),
        loadUserInfo: false,
        extraQueryParams: {
          ...
        }
      })

      manager.events.addAccessTokenExpiring(() => {
        let diff = Math.round(state.instance.expires_at - (Date.now() / 1000))
        console.log('[OIDC] Token expiring in ' + diff + 's --> silent refresh token will start soon ...')
      })

as you can see the addAccessTokenExpiring is called after the construction of the UserManager.

The only difference, that I can spot in the debug logs is that the log [SilentRenewService] _tokenExpiring: silent token renewal successful oidc-client-ts.js is comming earier with 2.4.0 than with 3.0.1. And our output [OIDC] Token expiring in ..s --> silent refresh token will start soon ... oidc.js:101 from the callback comes with 3.0.1 at the wrong time, just after the renewal of the token, not 90s before the expiry.

Let me know if I should test something else.

Attached you find the console logs (with oidc-client-ts debug enabled).

log-oidc-client-ts_2.4.0.txt
log-oidc-client-ts_3.0.1.txt

[pamapa]

The only difference, that I can spot in the debug logs is that the log [SilentRenewService] _tokenExpiring: silent token renewal successful oidc-client-ts.js is comming earier with 2.4.0 than with 3.0.1

Agree, could it be that in the 3.x run the renew itself against the IdP server was slower due to the server itself?
Here the diff:

diff --git "a/log-oidc-client-ts_3.0.1.txt" "b/log-oidc-client-ts_2.4.0.txt"
index 5001ca7..9e3647d 100644
--- "a/log-oidc-client-ts_3.0.1.txt"
+++ "b/log-oidc-client-ts_2.4.0.txt"
@@ -1,9 +1,9 @@
-[Timer('Access token expired')] timer completes in 104 oidc-client-ts.js
-[Timer('Access token expiring')] timer completes in 8 oidc-client-ts.js
-[Timer('Access token expired')] timer completes in 99 oidc-client-ts.js
-[Timer('Access token expiring')] timer completes in 3 oidc-client-ts.js
-[Timer('Access token expired')] timer completes in 94 oidc-client-ts.js
-[Timer('Access token expiring')] timer completes in -2 oidc-client-ts.js
+[Timer('Access token expired')] timer completes in 106 oidc-client-ts.js
+[Timer('Access token expiring')] timer completes in 10 oidc-client-ts.js
+[Timer('Access token expired')] timer completes in 101 oidc-client-ts.js
+[Timer('Access token expiring')] timer completes in 5 oidc-client-ts.js
+[Timer('Access token expired')] timer completes in 96 oidc-client-ts.js
+[Timer('Access token expiring')] timer completes in 0 oidc-client-ts.js
 [Timer('Access token expiring')] cancel: begin oidc-client-ts.js
 [Timer('Access token expiring')] raise: oidc-client-ts.js
 [SilentRenewService] _tokenExpiring: begin oidc-client-ts.js
@@ -11,6 +11,7 @@
 [UserManager] _loadUser: begin oidc-client-ts.js
 
 [WebStorageStateStore] get('user:https://my-oidc-provider.com:443/:my-oidc-client-id'): begin oidc-client-ts.js
+[OIDC] Token expiring in 89s --> silent refresh token will start soon ... oidc.js:101
 
 [UserManager] _loadUser: user storageString loaded oidc-client-ts.js
 [User.fromStorageString] begin oidc-client-ts.js
@@ -23,10 +24,10 @@
 [JsonService] getJson: begin oidc-client-ts.js
 [JsonService] appendExtraHeaders: begin oidc-client-ts.js
 [JsonService] getJson: url: https://my-oidc-provider.com:443/.well-known/openid-configuration oidc-client-ts.js
-[Timer('Access token expired')] timer completes in 89 oidc-client-ts.js
+[Timer('Access token expired')] timer completes in 91 oidc-client-ts.js
 XHRGET
 https://my-oidc-provider.com/.well-known/openid-configuration
-[HTTP/2 200  180ms]
+[HTTP/3 200  139ms]
 
 [JsonService] getJson: HTTP response received, status 200 oidc-client-ts.js
 [MetadataService] getMetadata: merging remote JSON with seed metadata oidc-client-ts.js
@@ -37,7 +38,7 @@ https://my-oidc-provider.com/.well-known/openid-configuration
 [JsonService] postForm: url: https://my-oidc-provider.com/oauth/token oidc-client-ts.js
 XHRPOST
 https://my-oidc-provider.com/oauth/token
-[HTTP/2 200  4361ms]
+[HTTP/3 200  228ms]
 
 [JsonService] postForm: HTTP response received, status 200 oidc-client-ts.js
 [TokenClient] exchangeRefreshToken: got response oidc-client-ts.js
@@ -66,7 +67,7 @@ oidc-client-ts.js
 [Timer('Access token expired')] cancel: begin oidc-client-ts.js
 [Timer('Access token expired')] init: using duration 121 oidc-client-ts.js
 [Event('User loaded')] raise: 
-Object { id_token: "yyy", session_state: null, access_token: "yyy", refresh_token: "xxx", token_type: "Bearer", scope: "openid profile email offline_access", profile: {…}, expires_at: 1724660322, state: undefined, url_state: undefined }
+Object { id_token: "yyy", session_state: null, access_token: "yyy", refresh_token: "xxx", token_type: "Bearer", scope: "openid profile email offline_access", profile: {…}, expires_at: 1724660191, state: undefined, url_state: undefined }
 oidc-client-ts.js
 
 [UserManager] getUser: begin oidc-client-ts.js
@@ -74,20 +75,20 @@ oidc-client-ts.js
 [WebStorageStateStore] get('user:https://my-oidc-provider.com:443/:my-oidc-client-id'): begin oidc-client-ts.js
 [UserManager] _loadUser: user storageString loaded oidc-client-ts.js
 [User.fromStorageString] begin oidc-client-ts.js
+[SilentRenewService] _tokenExpiring: silent token renewal successful oidc-client-ts.js
 [UserManager] getUser: user loaded oidc-client-ts.js
 [UserManagerEvents] load: begin oidc-client-ts.js
 [UserManagerEvents] load: access token present, remaining duration: 120 oidc-client-ts.js
 
 [UserManagerEvents] load: registering expiring timer, raising in 30 seconds oidc-client-ts.js
 [Timer('Access token expiring')] init: begin oidc-client-ts.js
-[Timer('Access token expiring')] init: skipping since already initialized for expiration at 1724660232 oidc-client-ts.js
+[Timer('Access token expiring')] init: skipping since already initialized for expiration at 1724660101 oidc-client-ts.js
 [UserManagerEvents] load: registering expired timer, raising in 121 seconds oidc-client-ts.js
 [Timer('Access token expired')] init: begin oidc-client-ts.js
-[Timer('Access token expired')] init: skipping since already initialized for expiration at 1724660323 oidc-client-ts.js
+[Timer('Access token expired')] init: skipping since already initialized for expiration at 1724660192 oidc-client-ts.js
 
-info: [OIDC] Token refreshed successfully! New token valid until 2024-08-26T10:18:42+02:00 IwsLogger.js
+info: [OIDC] Token refreshed successfully! New token valid until 2024-08-26T10:16:31+02:00 IwsLogger.js
 debug: [OIDC] Auth0 'digitalPortfolioAccess/roles' claim detected ... using claim 'digitalPortfolioAccess/roles' to obtain user roles IwsLogger.js
-[SilentRenewService] _tokenExpiring: silent token renewal successful oidc-client-ts.js
-[OIDC] Token expiring in 120s --> silent refresh token will start soon ... oidc.js:101
 [Timer('Access token expiring')] timer completes in 25 oidc-client-ts.js
 [Timer('Access token expired')] timer completes in 116 oidc-client-ts.js

What is suspicious is that i do not see logs like _signinStart....

[m4rc77]

@pamapa we have traced the problem and it is definitely related to #1312 respectively #1313.

The await in the following line is the culprit causing the effect we see:

oidc-client-ts/src/utils/Event.ts

Line 38 in 34528bf

await cb(...ev);

As a result of the await added in #1313, all the AccessTokenExpiring callbacks are called synchronously one after the other (which one could argue is not very common). Since we are using automaticSilentRenew, you respectively the internals of oidc-client-ts register a callback and later we do the same. Because of the await, your callback (the silent token renew) is completely done and then afterwards our AccessTokenExpiring callback is called, but at that point the token is already renewed and therefore we get some confusing results when checking expires_at as its not expiring any more.

In our case (as it is only for logging/debugging purposes) it does no harm. But for anyone else doing real live stuff in AccessTokenExpiring callbacks ... they need to know that if automaticSilentRenew is active, the AccessTokenExpiring callback will be called AFTER the token has been refreshed!.

[pamapa]

@m4rc77 Thanks for tracking this down. I have to think about this.