search

IdentityModel / oidc-client-js

OpenID Connect (OIDC) and OAuth2 protocol support for browser-based JavaScript applications
Apache License 2.0
2.43k stars 842 forks source link

AccessTokenExpiring AccessTokenExpired events delayed when waking from sleep #143

Closed kollhof closed 7 years ago

kollhof commented 8 years ago

We have a long running application that uses tokens with an expiry time of ca 5min. Everything works great until the the user resumes their machine from a sleep (> 5min). The application does not get notified of the token having expired and the silent renew does not happen for another 4min. Thus, the application is using an expired token for API calls, which then fail.

Steps to reproduce the issue (tested using Safari and Chrome on macOS Sierra):

The cause of this issue may be the due to the impl. of setTimeout(handler, delay) and it's use to trigger token events. When the computer wakes the handler is not being called immediately, despite the registered delay having passed. Instead it appears to wait for another delayms. See Point 7. at https://www.w3.org/TR/2011/WD-html5-20110525/timers.html#dom-windowtimers-settimeout

Fix suggestions:

Use (or reimplement) a timer class which will handle a wake from sleep after a token expiry. A couple ideas:

If this issue gets accepted, I will try to find some time to raise a PR with a fix for this.

Workaround:

Until a proper solution is implemented I am using something like the following.

function setupExpiryWorkaround(userManager, dispatch) {
  document.addEventListener('visibilitychange', async ()=> {
    // we only care when the user switches to the page.
    if (document.hidden === false) {
      // Getting the user will re-initialize all access-token events and the
      // associated timers to implement expiry checking/silent renewal
      const user = await userManager.getUser();

      if (user.expired) {
        // If the token has already expired, there won't be any new events
        // coming from oidc-client, so we need to handle this manually.
        dispatch(userExpired());
        let retryStep = 0;
        while (retryStep < signinRetries) {
          retryStep += 1;
          try {
            return await userManager.signinSilent();
          } catch (err) {
            // This may fail while the OS reconnects to a network
            // after waking up and we were a bit too quick trying
            // to perform the signin. We will retry a few times.
          }
        }
      }
    }
  });
}
brockallen commented 8 years ago

Hmm, so I guess timers in those browsers get cancelled in that situation... is there a JS event you can handle to get notified? Does the page get re-loaded (doesn't sound like it).

kollhof commented 8 years ago

The timers don't get cancelled, just delayed for an extra amount of time (the delay registered with setTimeout(handler, delay)).

The visibilitychange event appears to be reliable, would need to check across browsers and versions the lib is expected to work. It triggers immediately when returning to the page and even when waking from sleep, without ever having switched away from the browser. People also have used focus events and even webworkers for similar notification.

No, the page will not reload, which is exactly what I am looking for as it allows for long running apps and short token life time.

brockallen commented 8 years ago

The timers don't get cancelled, just delayed for an extra amount of time

Is this considered a bug in the browsers?

kollhof commented 8 years ago

The timers do appear to be implemented according to the spec: https://www.w3.org/TR/2011/WD-html5-20110525/timers.html#dom-windowtimers-settimeout (see point 7.)

brockallen commented 8 years ago

So in short, it sounds like when the device comes back from a sleeping state, the internal implementation in the browser re-initializes the timer queue from the delay value captured at the time of the call to setTimout, rather than the time the original timer was requested to fire.

Huh, I guess you learn something new every day.

brockallen commented 8 years ago

On a side note, you should always code your client to handle 401 status codes and get a new token (ideally using silent renew if possible).

brockallen commented 8 years ago

Do you know if this delay would also happen if the tab or browser itself is simply not the active window/app?

kollhof commented 8 years ago

I agree with needing to handle 401s as tokens could also have been revoked besides just expiring...

Delays may happen for inactive tabs as well. I believe having read very short delays are simply lengthened. I could not reproduce an issue using a timeout of two min (on Chrome and Safari on macOS):

setTimeout(()=> console.log(new Date()), 120* 1000).

It fired as expected, while I was working in a different app and the tab also not being the main one. This might be different on mobile where tabs could be treated differently to preserve power. I would have to spend a bit more time to investigate.

I believe the best option is to handle something like page re-activation using e.g. the visibilitychange event in conjunction with timers. This would make sure that events fire and renewing starts as soon as possible.

brockallen commented 8 years ago

I'd want this work to be done in the Timer class -- it'd need to keep track of the wall clock time when the event should trigger and on the visChange event re-init itself. I don't think it'd be that much of a change and this change is isolated.

brockallen commented 8 years ago

I made a change to help. Pushed 1.2.1-beta.3 to npm -- please test.

brockallen commented 7 years ago

I just released another beta. Please try it and let me know if it's working.

ErikSchierboom commented 7 years ago

Unfortunately, I still have this problem. After some searching, I can reproduce this issue in Chrome (v55.0.2883.87) on Windows 7 using the following steps:

  1. Open a browser tab with the page using the OIDC client set to auto renew.
  2. Open another browser tab and switch to it.
  3. Open some other (non-browser) applications and wait a while (at least until after the timer has expired).
  4. Go back to the page using the OIDC client.
  5. Verify that token has not been renewed.

If you look at the logging output, it looks like this:

INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 4
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: -1
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] Raising event: Access token expired
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe
INFO [OidcClientLogger] unchanged message from check session op iframe

Here you can see that the "Access token expired" event is raised, but that the token is not actually renewed. You can also see that there is a negative expiration "Access token expired timer expires in: -1".

If we don't switch to another application and just keep the OIDC client running, token renewal works fine.

kollhof commented 7 years ago

I don't think you will be able to ensure token renewal before coming back to a "sleeping" page, but you can shorten the time between activating the page and the next renewal. Implementing the workaround using visibilitychange, seems to achieve this without having to use short timers. But there is still a delay before you get a new token, i.e. waiting for the oidc server response. If you have a very interactive and chatty app, you could optimistically queue your requests while waiting for the new token, allowing the user to continue working with you application. You can also show some sort of progress indicator, telling the user that they are being signed in again and block them from performing certain actions. Though that might not be great from a UX point of view.

ErikSchierboom commented 7 years ago

@kollhof My goal isn't that the token renewal happens before I get back, but that token renewal does continue as normal when I get back. Which, at the moment, it does not. Token renewal is just stopped when I get back.

kollhof commented 7 years ago

Sorry, I misread. I thought it resumed renewing but just not quickly enough for you.

brockallen commented 7 years ago

Note on follow-up reading for myself: ejohn.org/blog/how-javascript-timers-work/

flieks commented 7 years ago

I also have this problem (chrome, windows 10) after testing the user-manager-sample. Now after F5, it tries to signinSilent but get this:


AccessTokenEvents.load
Log.js:55 canceling existing access token timers
Log.js:55 access token present, remaining duration: -767
Log.js:55 registering expired timer in: -766
Log.js:55 Timer.init timer Access token expired for duration: 1
Log.js:55 user loaded
Log.js:55 UserManagerEvents.load
Log.js:55 AccessTokenEvents.load
Log.js:55 canceling existing access token timers
Log.js:55 Timer.cancel:  Access token expired
Log.js:55 access token present, remaining duration: -767
Log.js:55 registering expired timer in: -766
Log.js:55 Timer.init timer Access token expired for duration: 1
Log.js:55 SessionMonitor._start; session_state: ob2CSmULwW3mdeYAIfU0-Wnwub4OuY0YTh8eguJwox0.aaaf153d2499091040afe9df23cd3511 , sub: 5ccf1143-53b7-498e-9876-1034abf88dcd
Log.js:55 MetadataService.getCheckSessionIframe
Log.js:55 MetadataService._getMetadataProperty check_session_iframe
Log.js:55 MetadataService.getMetadata
Log.js:55 getting metadata from http://localhost:5002/.well-known/openid-configuration
Log.js:55 JsonService.getJson http://localhost:5002/.well-known/openid-configuration
Log.js:55 HTTP response received, status 200
Log.js:55 json received
Log.js:55 metadata recieved
Log.js:55 Initializing check session iframe
Log.js:55 CheckSessionIFrame.start
Log.js:55 CheckSessionIFrame.stop
checksession:1 Refused to load the script 'http://localhost:57499/63bea10c2d0c43128cb565dd49c07655/browserLink' because it violates the following Content Security Policy directive: "script-src 'unsafe-inline' 'sha256-VDXN0nOpFPQ102CIVz+eimHA5e+wTeoUUQj5ZYbtn8w='".

Log.js:55Timer._callback; Access token expired timer expires in: 0
Log.js:55Timer.cancel:  Access token expired
Log.js:55Raising event: Access token expired
user-manager-sample.js:55 token expired
5Log.js:55unchanged message from check session op iframe
110Log.js:55 unchanged message from check session op iframe```
ErikSchierboom commented 7 years ago

Sorry to get back, but is there any progress on this?

brockallen commented 7 years ago

I've been quite busy, but I tentatively have Monday blocked on my calendar to do some OSS work (which includes this repo, and its outstanding bugs/issues. I want to get 1.3 released).

ErikSchierboom commented 7 years ago

@brockallen Thanks for the (quick) response! Good luck trackling this, the library is working perfectly otherwise.

brockallen commented 7 years ago

Thanks. I may end up reverting to the original suggestion on this -- the page visibility approach. The short timer with manual checking just hasn't seemed to work (unfortunately).

brockallen commented 7 years ago

I'll close this one and we'll track here: https://github.com/IdentityModel/oidc-client-js/issues/297

brockallen commented 7 years ago

@kollhof can you report back of these changes to the timer in 1.2.1 fixed your issue.

brockallen commented 7 years ago

@ErikSchierboom I started looking into this and can't really convince myself that the timer is the issue. We see in your log that INFO [OidcClientLogger] Raising event: Access token expired happens -- the SilentRenewService is not acting because we don't see the access token expiring event. Does silent renew work normally (meaning you see the normal "expiring" event in the logs)?

Perhaps your page is getting reloaded and the expiring timer thinks it's too far past expiration and just not initializing.

So yea, I'm thinking that changing the timers to use the visibilitychange will not affect the behavior.

brockallen commented 7 years ago

@ErikSchierboom or it might be that the 5 second granularity of the timer is too coarse when we're on the edge (meaning within 5 seconds) of both expiring and expired...

brockallen commented 7 years ago

So another thing that this investigation has made me aware of is that it is possible that the user is still logged into the token server, despite being past the token expiration. As of now the library does not try to re-renew past expiration even though it might work.... Hmm.

So perhaps a new feature to also try on expired is what should be done here.

ErikSchierboom commented 7 years ago

@brockallen I'll try and get a new log tomorrow, one where I don't switch applications or tabs (where the renewal should be fine) and one where I do switch applications (where the renewal doesn't happen).

Perhaps your strategy of re-trying works. I'd be happy to try a beta or anything similar.

brockallen commented 7 years ago

Ok, thx

ErikSchierboom commented 7 years ago

@brockallen I've managed to simulate the problem by interrupting the connection to the server temporarily. This causes frame timeouts, which is correct. Once the server comes back up though, I would expect a new token refresh request to be made, but it doesn't do that. Here is the log:

INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 58
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 59
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 59
INFO [OidcClientLogger] UserManager.signinSilentCallback
INFO [OidcClientLogger] _signinCallback
INFO [OidcClientLogger] IFrameNavigator.callback
INFO [OidcClientLogger] IFrameWindow.notifyParent
INFO [OidcClientLogger] posting url message to parent
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 58
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 59
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 59
INFO [OidcClientLogger] IFrameWindow._message
INFO [OidcClientLogger] IFrameWindow._cleanup
INFO [OidcClientLogger] Successful response from frame window
INFO [OidcClientLogger] _signinEnd
INFO [OidcClientLogger] OidcClient.processSigninResponse
INFO [OidcClientLogger] UrlUtility.parseUrlFragment
INFO [OidcClientLogger] WebStorageStateStore.remove 0136df37d2d147538872adbc556c030e
INFO [OidcClientLogger] SigninState.fromStorageString
INFO [OidcClientLogger] Received state from storage; validating response
INFO [OidcClientLogger] ResponseValidator.validateSigninResponse
INFO [OidcClientLogger] ResponseValidator._processSigninParams
INFO [OidcClientLogger] state validated
INFO [OidcClientLogger] state processed
INFO [OidcClientLogger] ResponseValidator._validateTokens
INFO [OidcClientLogger] Validating id_token and access_token
INFO [OidcClientLogger] ResponseValidator._validateIdTokenAndAccessToken
INFO [OidcClientLogger] ResponseValidator._validateIdToken
INFO [OidcClientLogger] JoseUtil.parseJwt
INFO [OidcClientLogger] MetadataService.getIssuer
INFO [OidcClientLogger] MetadataService._getMetadataProperty issuer
INFO [OidcClientLogger] MetadataService.getMetadata
INFO [OidcClientLogger] Returning metadata from settings
INFO [OidcClientLogger] metadata recieved
INFO [OidcClientLogger] Received issuer
INFO [OidcClientLogger] MetadataService.getSigningKeys
INFO [OidcClientLogger] Returning signingKeys from settings
INFO [OidcClientLogger] Received signing keys
INFO [OidcClientLogger] Validaing JWT; using clock skew (in seconds) of:  300
INFO [OidcClientLogger] JoseUtil.validateJwt
INFO [OidcClientLogger] JoseUtil._validateJwt
INFO [OidcClientLogger] JoseUtil.parseJwt
INFO [OidcClientLogger] JWT validation successful
INFO [OidcClientLogger] ResponseValidator._validateAccessToken
INFO [OidcClientLogger] JoseUtil.parseJwt
INFO [OidcClientLogger] JoseUtil.hashString eyJhbGciOiJSUzI1NiIsImtpZCI6IjcyMjdFRDhFRDI4RDRCREY4QTA1MUE0MTNCQ0MwN0JERkVGQzYwOTAiLCJ0eXAiOiJKV1QiLCJ4NXQiOiJjaWZ0anRLTlM5LUtCUnBCTzh3SHZmNzhZSkEifQ.eyJuYmYiOjE0OTA3ODEzMTcsImV4cCI6MTQ5MDc4MTM4NywiaXNzIjoiaHR0cDovL2xvY2FsaG9zdDozMDYwIiwiYXVkIjoiaHR0cDovL2xvY2FsaG9zdDozMDYwL3Jlc291cmNlcyIsImNsaWVudF9pZCI6InRrc3BvcnRhbCIsInN1YiI6WyI5NTE4OWE3Ni1jNGRkLTRjYzEtOTk4Ny04NDljMTZlZDk2MTkiLCI5NTE4OWE3Ni1jNGRkLTRjYzEtOTk4Ny04NDljMTZlZDk2MTkiXSwiYXV0aF90aW1lIjpbMTQ5MDc4MTA3MCwxNDkwNzgxMDcwXSwiaWRwIjpbImxvY2FsIiwibG9jYWwiXSwibmFtZSI6WyJyb290Iiwicm9vdCJdLCJjb250ZXh0TmFtZSI6ImJ1cGEiLCJjb250ZXh0RGF0YSI6IntcIkJ1c2luZXNzUGFydG5lcklkXCI6XCJiMjBlNTM0Zi1lYWM4LTQzYmYtOGFmMS0wZDFmMjBhOTEyNWFcIixcIkJ1c2luZXNzUGFydG5lck5hbWVcIjpcIkhlbGxvIEluYy5cIixcInJvbGVzXCI6W1wiQnVwYU1hbmFnZXJcIl19Iiwic2NvcGUiOlsib3BlbmlkIiwicHJvZmlsZSIsImNvbnRleHQiXSwiYW1yIjpbInB3ZCJdfQ.bSxLDdLulZOrMPVe73tbOwxdbR6IYMxD04hCv2HIGPoHV1yL8G1lFrFbPPk3Cv4a87HpfWOW193hHHGYdTXUlgkhVSER4aMK6abKrZIySAebrqaznyySGWALJdStciuUXHu99QMhrbuqCjCpKzR3_PG9j3vqBrtX4-as3N6zA_s6igCJAMmzOfq1js59qCDg5Tfz9D1Ss2rb1PW-NbGB8EFxJmdNstyemb0qhwe9cWiY1dp2gagk9WoFX1S_u8BiJKghiNNOTTMD5psKDp4mXXorxK5C1I1Hxr1S5L4CMSPAw6vd3QjvxLFk5KwxGkJikjhIVNpMT1EVq6lBzX4Ml058sK1jd96XWZDUz_2PIQHLvNlZaivQ2TRiK--2cqHbz7qhJdKOcyIp2Vkrbu3y6cY4vBlPTFfxLVug25pv_BIghO4UNUqSy-23PKJApf9zrUj4f8cSp713yj4uTf84j2AoTDKYDBZ3c5XZ9BPTeWUiFWKzIW5jg5uCbsAQ8U2nfU_e4_X67eW_bFviNySZGu0x25gZ_b7crP4nyuvURcvIizXj8wcU8cOmEAv9kUQiSk5wGGMH92zJoRGwDPN8DGbWWYpQU7yjbvRw3rhVU_uC8ipVTt2wka-rAcEaNFyTJgrMZwh0tW9mHkBewwEdAEekaQ3qyVuSP3d-UjnvhVk sha256
INFO [OidcClientLogger] JoseUtil.hexToBase64Url dec1e061c73c2d3c4facaac319612070
INFO [OidcClientLogger] tokens validated
INFO [OidcClientLogger] ResponseValidator._processClaims
INFO [OidcClientLogger] response is OIDC, processing claims
INFO [OidcClientLogger] ResponseValidator._filterProtocolClaims, incoming claims: Object {nbf: 1490781317, exp: 1490781617, iss: "http://localhost:3060", aud: "tksportal", nonce: "a3d6dd7061b4479ab1e2425666fe808e"…}
INFO [OidcClientLogger] protocol claims filtered Object {sub: "95189a76-c4dd-4cc1-9987-849c16ed9619", auth_time: 1490781070, idp: "local", amr: Array[1]}
INFO [OidcClientLogger] not loading user info
INFO [OidcClientLogger] claims processed
INFO [OidcClientLogger] got signin response
INFO [OidcClientLogger] _storeUser storing user
INFO [OidcClientLogger] User.toStorageString
INFO [OidcClientLogger] WebStorageStateStore.set user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user stored
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 70
INFO [OidcClientLogger] registering expiring timer in: 10
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 10
INFO [OidcClientLogger] registering expired timer in: 71
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 71
INFO [OidcClientLogger] Raising event: User loaded
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 70
INFO [OidcClientLogger] registering expiring timer in: 10
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 10
INFO [OidcClientLogger] registering expired timer in: 71
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 71
INFO [OidcClientLogger] Silent token renewal successful
INFO [OidcClientLogger] Timer._callback; Access token expiring timer expires in: 5
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 66
INFO [OidcClientLogger] Timer._callback; Access token expiring timer expires in: 0
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Raising event: Access token expiring
INFO [OidcClientLogger] SilentRenewService automatically renewing access token
INFO [OidcClientLogger] UserManager.signinSilent
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] _signin
INFO [OidcClientLogger] _signinStart
INFO [OidcClientLogger] IFrameWindow.ctor
INFO [OidcClientLogger] got navigator window handle
INFO [OidcClientLogger] OidcClient.createSigninRequest
INFO [OidcClientLogger] MetadataService.getAuthorizationEndpoint
INFO [OidcClientLogger] MetadataService._getMetadataProperty authorization_endpoint
INFO [OidcClientLogger] MetadataService.getMetadata
INFO [OidcClientLogger] Returning metadata from settings
INFO [OidcClientLogger] metadata recieved
INFO [OidcClientLogger] Received authorization endpoint http://localhost:3060/connect/authorize
INFO [OidcClientLogger] SigninState.toStorageString
INFO [OidcClientLogger] WebStorageStateStore.set 7412c21b130541a289dc5091d9cb8a75
INFO [OidcClientLogger] got signin request
INFO [OidcClientLogger] IFrameWindow.navigate
INFO [OidcClientLogger] Using timeout of: 5000
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 61
INFO [OidcClientLogger] automaticSilentRenew is configured, setting up silent renew
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] monitorSession is configured, setting up session monitor
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] access token present, remaining duration: 59
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 60
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 60
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 59
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 60
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 60
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 59
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 60
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 60
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 58
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 59
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 59
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 58
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 59
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 59
INFO [OidcClientLogger] UserManager.signinSilentCallback
INFO [OidcClientLogger] _signinCallback
INFO [OidcClientLogger] IFrameNavigator.callback
INFO [OidcClientLogger] IFrameWindow.notifyParent
INFO [OidcClientLogger] posting url message to parent
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 58
INFO [OidcClientLogger] registering expiring timer in: 1
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 1
INFO [OidcClientLogger] registering expired timer in: 59
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 59
INFO [OidcClientLogger] IFrameWindow._message
INFO [OidcClientLogger] IFrameWindow._cleanup
INFO [OidcClientLogger] Successful response from frame window
INFO [OidcClientLogger] _signinEnd
INFO [OidcClientLogger] OidcClient.processSigninResponse
INFO [OidcClientLogger] UrlUtility.parseUrlFragment
INFO [OidcClientLogger] WebStorageStateStore.remove 7412c21b130541a289dc5091d9cb8a75
INFO [OidcClientLogger] SigninState.fromStorageString
INFO [OidcClientLogger] Received state from storage; validating response
INFO [OidcClientLogger] ResponseValidator.validateSigninResponse
INFO [OidcClientLogger] ResponseValidator._processSigninParams
INFO [OidcClientLogger] state validated
INFO [OidcClientLogger] state processed
INFO [OidcClientLogger] ResponseValidator._validateTokens
INFO [OidcClientLogger] Validating id_token and access_token
INFO [OidcClientLogger] ResponseValidator._validateIdTokenAndAccessToken
INFO [OidcClientLogger] ResponseValidator._validateIdToken
INFO [OidcClientLogger] JoseUtil.parseJwt
INFO [OidcClientLogger] MetadataService.getIssuer
INFO [OidcClientLogger] MetadataService._getMetadataProperty issuer
INFO [OidcClientLogger] MetadataService.getMetadata
INFO [OidcClientLogger] Returning metadata from settings
INFO [OidcClientLogger] metadata recieved
INFO [OidcClientLogger] Received issuer
INFO [OidcClientLogger] MetadataService.getSigningKeys
INFO [OidcClientLogger] Returning signingKeys from settings
INFO [OidcClientLogger] Received signing keys
INFO [OidcClientLogger] Validaing JWT; using clock skew (in seconds) of:  300
INFO [OidcClientLogger] JoseUtil.validateJwt
INFO [OidcClientLogger] JoseUtil._validateJwt
INFO [OidcClientLogger] JoseUtil.parseJwt
INFO [OidcClientLogger] JWT validation successful
INFO [OidcClientLogger] ResponseValidator._validateAccessToken
INFO [OidcClientLogger] JoseUtil.parseJwt
INFO [OidcClientLogger] JoseUtil.hashString eyJhbGciOiJSUzI1NiIsImtpZCI6IjcyMjdFRDhFRDI4RDRCREY4QTA1MUE0MTNCQ0MwN0JERkVGQzYwOTAiLCJ0eXAiOiJKV1QiLCJ4NXQiOiJjaWZ0anRLTlM5LUtCUnBCTzh3SHZmNzhZSkEifQ.eyJuYmYiOjE0OTA3ODEzMjksImV4cCI6MTQ5MDc4MTM5OSwiaXNzIjoiaHR0cDovL2xvY2FsaG9zdDozMDYwIiwiYXVkIjoiaHR0cDovL2xvY2FsaG9zdDozMDYwL3Jlc291cmNlcyIsImNsaWVudF9pZCI6InRrc3BvcnRhbCIsInN1YiI6WyI5NTE4OWE3Ni1jNGRkLTRjYzEtOTk4Ny04NDljMTZlZDk2MTkiLCI5NTE4OWE3Ni1jNGRkLTRjYzEtOTk4Ny04NDljMTZlZDk2MTkiXSwiYXV0aF90aW1lIjpbMTQ5MDc4MTA3MCwxNDkwNzgxMDcwXSwiaWRwIjpbImxvY2FsIiwibG9jYWwiXSwibmFtZSI6WyJyb290Iiwicm9vdCJdLCJjb250ZXh0TmFtZSI6ImJ1cGEiLCJjb250ZXh0RGF0YSI6IntcIkJ1c2luZXNzUGFydG5lcklkXCI6XCJiMjBlNTM0Zi1lYWM4LTQzYmYtOGFmMS0wZDFmMjBhOTEyNWFcIixcIkJ1c2luZXNzUGFydG5lck5hbWVcIjpcIkhlbGxvIEluYy5cIixcInJvbGVzXCI6W1wiQnVwYU1hbmFnZXJcIl19Iiwic2NvcGUiOlsib3BlbmlkIiwicHJvZmlsZSIsImNvbnRleHQiXSwiYW1yIjpbInB3ZCJdfQ.zQQRj1pvW-Lkww3Gl3jTwXi7kSlZRsQpHJjKXjWg9teEV78nQRHntZ0xEkCdUFd4dm-ZAAaRtUFMpzizB_bK_x1ayGdDLLKq993TgzWXDqHiU5B5h3RMqM65-37MlghDIQMoPACw2iGP3kLy5xHNf6dseleizAYUOXsMXw2lAXnrQS5Qscc1flYdyutqf1D3ieA73bskO56bdX308bbiTTfjH5tGd8NHFFBhyEPZniFykHX8WgCJQMmtEjAD2VsTmpHdytKDmKUK5e2KKOFdN2uRfRDxdTWIxY4xDqO_K2dHAKLxCxbfLZblB9sTU48eXQiG6f7bWLc6zsckgMymiaGlOTIsVO-c1XUxjHQDjFKjOTF7h1SZxVQAi1ds4eSXjPRc-JtupJX2Ii0CQL9zmJOc1D1thdU1bKJzj8vzrCr9N7sVkwGAcGLJ3YL9zE9uP9EoljfOZ_Kc-5RJ1YsquQbLdCfE5jDlgG1XpEmaUDQC91Up0eybguH8whpb5o_8J2XafrDRgEtME6U5P3fXGITfbMeR6sWQhh_0tATHM9X4m-ghNaymC3KzvKe6MDm_kSwV0UeFdeyqKgxBDECv0dRcd7JU_xuwmP4FPIpZDIeoq6pldE_-wHyeyq6AcqyGOAX-cd_zqE5XhmXkaSzc8XaH2-8L2-ZZ06By8fyVflU sha256
INFO [OidcClientLogger] JoseUtil.hexToBase64Url c073eefeef5f1b0f160780c5659296bf
INFO [OidcClientLogger] tokens validated
INFO [OidcClientLogger] ResponseValidator._processClaims
INFO [OidcClientLogger] response is OIDC, processing claims
INFO [OidcClientLogger] ResponseValidator._filterProtocolClaims, incoming claims: Object {nbf: 1490781329, exp: 1490781629, iss: "http://localhost:3060", aud: "tksportal", nonce: "f2686b46b231451eb65eca0b2e88a0cc"…}
INFO [OidcClientLogger] protocol claims filtered Object {sub: "95189a76-c4dd-4cc1-9987-849c16ed9619", auth_time: 1490781070, idp: "local", amr: Array[1]}
INFO [OidcClientLogger] not loading user info
INFO [OidcClientLogger] claims processed
INFO [OidcClientLogger] got signin response
INFO [OidcClientLogger] _storeUser storing user
INFO [OidcClientLogger] User.toStorageString
INFO [OidcClientLogger] WebStorageStateStore.set user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user stored
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 70
INFO [OidcClientLogger] registering expiring timer in: 10
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 10
INFO [OidcClientLogger] registering expired timer in: 71
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 71
INFO [OidcClientLogger] Raising event: User loaded
INFO [OidcClientLogger] UserManager.getUser
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] user loaded
INFO [OidcClientLogger] UserManagerEvents.load
INFO [OidcClientLogger] AccessTokenEvents.load
INFO [OidcClientLogger] canceling existing access token timers
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] access token present, remaining duration: 70
INFO [OidcClientLogger] registering expiring timer in: 10
INFO [OidcClientLogger] Timer.init timer Access token expiring for duration: 10
INFO [OidcClientLogger] registering expired timer in: 71
INFO [OidcClientLogger] Timer.init timer Access token expired for duration: 71
INFO [OidcClientLogger] Silent token renewal successful
INFO [OidcClientLogger] Timer._callback; Access token expiring timer expires in: 5
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 66
INFO [OidcClientLogger] Timer._callback; Access token expiring timer expires in: 0
INFO [OidcClientLogger] Timer.cancel:  Access token expiring
INFO [OidcClientLogger] Raising event: Access token expiring
INFO [OidcClientLogger] SilentRenewService automatically renewing access token
INFO [OidcClientLogger] UserManager.signinSilent
INFO [OidcClientLogger] _loadUser
INFO [OidcClientLogger] WebStorageStateStore.get user:http://localhost:3060:tksportal
INFO [OidcClientLogger] user storageString loaded
INFO [OidcClientLogger] User.fromStorageString
INFO [OidcClientLogger] _signin
INFO [OidcClientLogger] _signinStart
INFO [OidcClientLogger] IFrameWindow.ctor
INFO [OidcClientLogger] got navigator window handle
INFO [OidcClientLogger] OidcClient.createSigninRequest
INFO [OidcClientLogger] MetadataService.getAuthorizationEndpoint
INFO [OidcClientLogger] MetadataService._getMetadataProperty authorization_endpoint
INFO [OidcClientLogger] MetadataService.getMetadata
INFO [OidcClientLogger] Returning metadata from settings
INFO [OidcClientLogger] metadata recieved
INFO [OidcClientLogger] Received authorization endpoint http://localhost:3060/connect/authorize
INFO [OidcClientLogger] SigninState.toStorageString
INFO [OidcClientLogger] WebStorageStateStore.set 312032a196cc4b169f517e059ffba375
INFO [OidcClientLogger] got signin request
INFO [OidcClientLogger] IFrameWindow.navigate
INFO [OidcClientLogger] Using timeout of: 5000
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 61
oidc-client.min.js:74 GET http://localhost:3060/connect/authorize?client_id=tksportal&redirect_uri=ht…a9BZlvxpsbv14galZ7ZTHWBf635u3P7tGu1H3L_e0gojPwtXUUk2YAJ-qBp60S4043BUIU_Nr0 500 (Internal Server Error)
t.navigate @ oidc-client.min.js:74
(anonymous) @ oidc-client.min.js:74
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 56
INFO [OidcClientLogger] IFrameWindow._timeout
INFO [OidcClientLogger] IFrameWindow._cleanup
aurelia-logging-console.js:54 ERROR [OidcClientLogger] Frame window timed out
error @ aurelia-logging-console.js:54
(anonymous) @ aurelia-logging.js:44
OidcClientLogger.error @ oidcclientlogger.ts:14
t.error @ oidc-client.min.js:1
t._error @ oidc-client.min.js:74
t._timeout @ oidc-client.min.js:74
aurelia-logging-console.js:54 ERROR [OidcClientLogger] Error from signinSilent: Frame window timed out
error @ aurelia-logging-console.js:54
(anonymous) @ aurelia-logging.js:44
OidcClientLogger.error @ oidcclientlogger.ts:14
t.error @ oidc-client.min.js:1
(anonymous) @ oidc-client.min.js:75
INFO [OidcClientLogger] UserManagerEvents._raiseSilentRenewError Frame window timed out
INFO [OidcClientLogger] Raising event: Silent renew error
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 51
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 46
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 41
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 36
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 31
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 26
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 21
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 16
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 11
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 6
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: 1
INFO [OidcClientLogger] Timer._callback; Access token expired timer expires in: -4
INFO [OidcClientLogger] Timer.cancel:  Access token expired
INFO [OidcClientLogger] Raising event: Access token expired

After that last line in the log, nothing happens anymore; there is no further logging.

brockallen commented 7 years ago

I've managed to simulate the problem by interrupting the connection to the server temporarily. This causes frame timeouts, which is correct. Once the server comes back up though, I would expect a new token refresh request to be made, but it doesn't do that.

This is how it's currently coded. So in short, once the silent renew fails, it just stops. The assumption with this behavior was that if silent renew fails, it's probably due to expired session at the OP, so there's no good reason to keep trying. I think it's hard to distinguish all the different scenarios, so if it fails for any reason then we're done.

So I think the problem/issue you raised on this thread is really unrelated to this original issue I think.

brockallen commented 7 years ago

I'd still like to hear from @kollhof if these changes to the timer in 1.2.1 fixed your issue.

kollhof commented 7 years ago

Using shorter timers to repeatedly check if a token has expired wasn't enough. The user still had to wait 5s before being able to use the application. We are still using the page-visability workaround that I initially described. This will ensure a token renewal as soon as possible.

ErikSchierboom commented 7 years ago

@brockallen Ah, so that's another issue then. However, I do believe that I saw the exact same behavior with my original issue, with very similar output. I'll try to reproduce that situation.

brockallen commented 7 years ago

Ah, so that's another issue then.

If you're not satisfied with my above explanation, then please open a new issue.

ErikSchierboom commented 7 years ago

@brockallen I'll do some more researching. Thanks for the help!

brockallen commented 7 years ago

Using shorter timers to repeatedly check if a token has expired wasn't enough. The user still had to wait 5s before being able to use the application.

This is disappointing. I'll spend some more time on #297.