search

authts / oidc-client-ts

OpenID Connect (OIDC) and OAuth2 protocol support for browser-based JavaScript applications
https://authts.github.io/oidc-client-ts/
Apache License 2.0
1.33k stars 197 forks source link

Behaviour of addAccessTokenExpiring callback changed between 2.4.0 and 3.0.1 #1624

Open m4rc77 opened 4 weeks ago

m4rc77 commented 4 weeks ago

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:

With 3.0.1

Could this be a Bug?

pamapa commented 3 weeks ago

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

Revision: 5af4847a005f5204906ee0946d48656a6da8bba3
Author: pamapa <pamapa@users.noreply.github.com>
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 commented 2 weeks ago

@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 commented 2 weeks ago

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....