[MSAL] Settings Sync logs out after a few hours

[winstliu]

Does this issue occur when all extensions are disabled?: Didn't try without extensions because this is a multi-hour repro and I need to stay productive, sorry!

Version: 1.94.0-insider (user setup)
Commit: 1926933
Date: 2024-09-23T05:12:01.964Z
Electron: 30.5.0
ElectronBuildId: 10198947
Chromium: 124.0.6367.243
Node.js: 20.16.0
V8: 12.4.254.20-electron.0
OS: Windows_NT x64 10.0.22631

Steps to Reproduce:

1. Enable MSAL
2. Log into Settings Sync with a Microsoft account
3. Wait a few hours and notice you're logged out

https://gist.github.com/winstliu/b858f9e8f600301676a04cdd3f16f3cb

[TylerLeonhardt]

Can you include the Window & Microsoft authentication logs as well?

I'm gonna loop in @sandy081 to help out understanding the Settings Sync stuff

[winstliu]

Window: https://gist.github.com/winstliu/183e19bbdec127752e47723fc8da1796 (it's verbose)
Microsoft auth: https://gist.github.com/winstliu/614a4c4fc7fc35f249c97ac6099c2c02

[winstliu]

@sandy081 any progress here? I'm still continuously getting logged out.

[TylerLeonhardt]

Sandeep and I will sit down soon to discuss these MSAL related bugs. My suspicion is that Settings Sync is keeping track of the id of a session, rather than the account being used with Settings Sync. The session id is suppose to be different every time a token is refreshed but the account should stay the same.

[alex180500]

Please fix this

[sandy081]

@TylerLeonhardt Given the latest improvements in auth and settings sync areas, Should we ask user to try insiders and see if the issue can be still reproducible? Or do you think these changes are not related to this issue?

[TylerLeonhardt]

@sandy081 I don't think those changes were related to this issue and this should be investigated

[winstliu]

Indeed, this is still happening on 0c9dd26

[sandy081]

@TylerLeonhardt I believe following logging explains why settings sync is logging out

2024-09-25 11:52:47.722 [info] Settings Sync: Updating due to token failure
2024-09-25 11:52:47.729 [trace] Settings Sync: Updating the token for the account winstonliu@microsoft.com
2024-09-25 11:52:47.729 [trace] Settings Sync: Token updated for the account winstonliu@microsoft.com
2024-09-25 11:52:47.742 [info] Settings Sync: Reset current session
2024-09-25 11:52:47.742 [info] Settings Sync: Updating due to auth failure
2024-09-25 11:52:47.745 [trace] Settings Sync: Account status changed from available to unavailable

My suspicion is that when the token fails for the first time, workbench tries to refresh the token (requesting auth service for sessions) and I believe the token that is given back is not refreshed and probably the same token. Therefore, when workbench tries to sync again it fails again and Settings Sync logs out to prevent recursive invalid auth requests.

@winstliu Can you please share the window log again when this happens again? This might help in prove the theory.

[sandy081]

@winstliu Also share the settings sync log. Over all following logs needed

• F1 > Open View... > Window
• F1 > Open View... > Settings Sync
• F1 > Open View... > Microsoft

[TylerLeonhardt]

I think I found the issue... @sandy081 your analysis really helped! PR sent.

[TylerLeonhardt]

Omg... I think I figured this one out for real this time. In some places we use jsonwebtoken.verify passing in the idToken to verify audience. This also verifies expiration.

Talking with MSAL folks, apparently publicClient.acquireTokenSilent(...) will only auto-refresh access tokens if they're near expiration. Not id tokens. So this API does return expired idTokens thinking no one will verify them. This wasn't clear at all from the SDK or docs.

The solution is to manually check the expiration of the idtoken and refresh it if it's close.

[winstliu]

Appreciate your persistence here, but it looks like it's still something else :(
Version: 1.97.0-insider (user setup)
Commit: 21a129e
Date: 2024-12-13T12:38:52.505Z
Electron: 32.2.6
ElectronBuildId: 10629634
Chromium: 128.0.6613.186
Node.js: 20.18.1
V8: 12.8.374.38-electron.0
OS: Windows_NT x64 10.0.26100

As usual, let me know which logs would be helpful.

[TylerLeonhardt]

logs would be helpful. Trace level.

• F1 > Open View... > Window
• F1 > Open View... > Settings Sync
• F1 > Open View... > Microsoft Auth

[winstliu]

Window: https://gist.github.com/winstliu/ecc822a8bb9f55067b5797abea252430 (I believe this might be truncated, I'm pretty sure I enabled Settings Sync at 12:30)
Settings Sync: https://gist.github.com/winstliu/193cb9a8caae483db34ec105b5130f2b
Microsoft Auth: https://gist.github.com/winstliu/09684962a4a2b0641153a89d1872935e (this one's even more truncated, with only results from the past ~6 minutes)

[TylerLeonhardt]

I am able to repro only on the broker side... I wonder if my fix doesn't work in the broker scenario. That would be really sad...

[TylerLeonhardt]

Confirmed... the broker flow does not support forceRefresh... I need to once again be creative.

[TylerLeonhardt]

Alright @winstliu ... my fingers are crossed. Tomorrow will tell... let me know how it goes, and please do attach logs again if you see the issue (I added another log statement).

[winstliu]

Yes, this seems to be fixed!!! Thanks 😁

[TylerLeonhardt]

FINALLY 😭