Microsoft-authentication-library-for-dotnet: [Bug] App Gets stuck in "Client Request Loop" due to User.ReadBasic.All scope

Created on 19 Jan 2021  Â·  14Comments  Â·  Source: AzureAD/microsoft-authentication-library-for-dotnet

Logs and Network traces
I will work on getting logs.

Which Version of MSAL are you using ?
MSAL 4.18 works without issue, but upgrading beyond 4.18 causes this exception loop to occur.

Platform
UWP

What authentication flow has the issue?

  • Desktop / Mobile

    • [X] Interactive

    • [ ] Integrated Windows Auth

    • [ ] Username Password

    • [ ] Device code flow (browserless)

Other? - please describe;

Is this a new or existing app?
The app (Ink Calendar) is in production, I haven't upgraded MSAL, but started seeing this issue when upgrading beyond 4.18

Repro


try
{
    authResult = await PublicClientApp.AcquireTokenSilent(scopes, firstAccount)
                                                     .ExecuteAsync();
}
catch (MsalUiRequiredException ex)
{
    Debug.WriteLine($"MsalUiRequiredException: {ex.Message}");

    // This is where the looping failure occurs: ↓
    authResult = await PublicClientApp.AcquireTokenInteractive(scopes)
                                                  .ExecuteAsync()
                                                  .ConfigureAwait(false);
}
return authResult.AccessToken;

Expected behavior
I expect versions beyond 4.18 to work as well as 4.18 does.

Actual behavior
When the app tries to upload the ink file which is being saved there is an exception thrown "the file is in use by another process" then stops and tries again later. When upgrading MSAL beyond 4.18 this exception throws the MS Graph identity into a loop which asks the user to login again, over and over and over. Closing the app is the only way to stop the loop.

Possible Solution
Stay on 4.18

answered question
Source
picture TheJoeFin

All 14 comments

Please try to get logs. In the meantime, could you tell me what scopes you ask for?

bgavrilMS picture bgavrilMS on 19 Jan 2021

Scopes
User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder

For logging do you want logs on the good package (4.18) and the latest package I'm seeing the exception loop? Or just when I'm seeing the exception loop?

TheJoeFin picture TheJoeFin on 19 Jan 2021

Latest MSAL version to see the actual bug

bgavrilMS picture bgavrilMS on 19 Jan 2021
👍1

Here is the end of the debug output. This should include a successful OneDrive sync and the exception loop at the end. When MSAL failed and entered the exception loop I closed the app. Let me know if you need more or something else

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] === Token Acquisition (SilentRequest) started:

    Authority Host: login.microsoftonline.com 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Refresh token found in the cache? - True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Resolving authority endpoints... Already resolved? - TRUE 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Checking client info returned from the server.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Saving Token Response to cache.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Subject not present in Id token 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Saving AT in cache and removing overlapping ATs... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Looking for scopes for the authority in the cache which intersect with User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Intersecting scope entries count - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Matching entries after filtering by user - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Saving Id Token and Account in cache ... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] Saving RT in cache... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48] Serializing token cache with 1 items.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:48 - a675e0da-a7ac-4db6-a11d-4828ca6e26d6] === Token Acquisition finished successfully. An access token was returned with Expiration Time: 01/20/2021 12:19:48 +00:00 === 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49] Found 1 cache accounts and 1 broker accounts 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] MSAL MSAL.UAP with assembly version '4.24.0.0'. CorrelationId(dbe1d4d4-e1f6-4029-85cc-ae5914c46057) 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] === AcquireTokenSilent Parameters === 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] LoginHint provided: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Account provided: True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] ForceRefresh: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] 
=== Request Data ===
Authority Provided? - True
Scopes - User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - dbe1d4d4-e1f6-4029-85cc-ae5914c46057

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] === Token Acquisition (SilentRequest) started:

    Authority Host: login.microsoftonline.com 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Refresh token found in the cache? - True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Resolving authority endpoints... Already resolved? - TRUE 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Checking client info returned from the server.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Saving Token Response to cache.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Subject not present in Id token 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Saving AT in cache and removing overlapping ATs... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Looking for scopes for the authority in the cache which intersect with User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Intersecting scope entries count - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Matching entries after filtering by user - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Saving Id Token and Account in cache ... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] Saving RT in cache... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49] Serializing token cache with 1 items.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:19:49 - dbe1d4d4-e1f6-4029-85cc-ae5914c46057] === Token Acquisition finished successfully. An access token was returned with Expiration Time: 01/20/2021 12:19:49 +00:00 === 
CheckForFilesToDownload 0 items rectified
The thread 0x5a54 has exited with code 0 (0x0).
The thread 0x1528 has exited with code 0 (0x0).
The thread 0x4950 has exited with code 0 (0x0).
The thread 0x4a78 has exited with code 0 (0x0).
CheckForDownloadsTimer_Tick, Internet:True isUploading:False isDownloading:False
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18] Found 1 cache accounts and 1 broker accounts 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] MSAL MSAL.UAP with assembly version '4.24.0.0'. CorrelationId(d44fe76d-b145-4c25-99b3-72766dba235e) 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] === AcquireTokenSilent Parameters === 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] LoginHint provided: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Account provided: True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] ForceRefresh: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] 
=== Request Data ===
Authority Provided? - True
Scopes - User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - d44fe76d-b145-4c25-99b3-72766dba235e

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] === Token Acquisition (SilentRequest) started:

    Authority Host: login.microsoftonline.com 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Refresh token found in the cache? - True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Resolving authority endpoints... Already resolved? - TRUE 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Checking client info returned from the server.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Saving Token Response to cache.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Subject not present in Id token 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Saving AT in cache and removing overlapping ATs... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Looking for scopes for the authority in the cache which intersect with User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Intersecting scope entries count - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Matching entries after filtering by user - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Saving Id Token and Account in cache ... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] Saving RT in cache... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18] Serializing token cache with 1 items.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:18 - d44fe76d-b145-4c25-99b3-72766dba235e] === Token Acquisition finished successfully. An access token was returned with Expiration Time: 01/20/2021 12:20:18 +00:00 === 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19] Found 1 cache accounts and 1 broker accounts 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] MSAL MSAL.UAP with assembly version '4.24.0.0'. CorrelationId(44ab36f9-7fd3-4339-a9e8-e7a50105b7b8) 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] === AcquireTokenSilent Parameters === 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] LoginHint provided: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Account provided: True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] ForceRefresh: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] 
=== Request Data ===
Authority Provided? - True
Scopes - User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] === Token Acquisition (SilentRequest) started:

    Authority Host: login.microsoftonline.com 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Refresh token found in the cache? - True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Resolving authority endpoints... Already resolved? - TRUE 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Checking client info returned from the server.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Saving Token Response to cache.. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Subject not present in Id token 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Saving AT in cache and removing overlapping ATs... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Looking for scopes for the authority in the cache which intersect with User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Intersecting scope entries count - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Matching entries after filtering by user - 1 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Saving Id Token and Account in cache ... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] Saving RT in cache... 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19] Serializing token cache with 1 items.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:19 - 44ab36f9-7fd3-4339-a9e8-e7a50105b7b8] === Token Acquisition finished successfully. An access token was returned with Expiration Time: 01/20/2021 12:20:19 +00:00 === 
CheckForFilesToDownload 0 items rectified
The thread 0x360c has exited with code 0 (0x0).
The thread 0x3970 has exited with code 0 (0x0).
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
'InkCalendar.exe' (CoreCLR: CoreCLR_UWP_Domain): Loaded 'C:\Program Files\WindowsApps\Microsoft.NET.CoreFramework.Debug.2.2_2.2.29301.2_x64__8wekyb3d8bbwe\System.Diagnostics.StackTrace.dll'. Skipped loading symbols. Module is optimized and the debugger option 'Just My Code' is enabled.
System.IO.FileNotFoundException: The system cannot find the file specified. (Exception from HRESULT: 0x80070002)
   at InkCalendar.Helpers.ViewStateHelpers.GetViewStateForCalInkItem(CalendarInkItem calendarInkItem, SettingsHelper settingsHelper)
The thread 0x60f4 has exited with code 0 (0x0).
The thread 0x1564 has exited with code 0 (0x0).
The thread 0x5dd4 has exited with code 0 (0x0).
The thread 0x5e48 has exited with code 0 (0x0).
Background rendering finished: 423932 ticks - 42 ms
Background rendering finished: 426526 ticks - 42 ms
Background generation finished: 380 ticks - 0 ms
Background generation finished: 839 ticks - 0 ms
Background rendering finished: 631795 ticks - 63 ms
Background rendering finished: 678699 ticks - 67 ms
Exception thrown: 'System.IO.FileNotFoundException' in System.Private.CoreLib.dll
System.IO.FileNotFoundException: The system cannot find the file specified. (Exception from HRESULT: 0x80070002)
   at InkCalendar.Helpers.ViewStateHelpers.GetViewStateForCalInkItem(CalendarInkItem calendarInkItem, SettingsHelper settingsHelper)
The thread 0x3620 has exited with code 0 (0x0).
The thread 0x114c has exited with code 0 (0x0).
The thread 0x3da0 has exited with code 0 (0x0).
The thread 0x5530 has exited with code 0 (0x0).
CheckForDownloadsTimer_Tick, Internet:True isUploading:False isDownloading:False
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48] Deserialized 1 items to token cache.  
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48] Found 1 cache accounts and 1 broker accounts 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] MSAL MSAL.UAP with assembly version '4.24.0.0'. CorrelationId(49c19e9e-c30e-46e4-b021-3cd1ee658796) 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] === AcquireTokenSilent Parameters === 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] LoginHint provided: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Account provided: True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] ForceRefresh: False 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] 
=== Request Data ===
Authority Provided? - True
Scopes - User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - 49c19e9e-c30e-46e4-b021-3cd1ee658796

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] === Token Acquisition (SilentRequest) started:

    Authority Host: login.microsoftonline.com 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Refresh token found in the cache? - True 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Resolving authority endpoints... Already resolved? - TRUE 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Response status code does not indicate success: 400 (BadRequest).  
MSAL: Warning (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Request retry failed. 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] HttpStatusCode: 400: BadRequest 
MSAL: Error (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Exception type: Microsoft.Identity.Client.MsalUiRequiredException
, ErrorCode: invalid_grant
HTTP StatusCode 400
CorrelationId 49c19e9e-c30e-46e4-b021-3cd1ee658796

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] [Throttling] MsalUiRequiredException encountered - throttling for 120 seconds.  
MSAL: Warning (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Refreshing the RT failed. Is AAD down? False. Is there an AT in the cache that is usable? False  
MSAL: Warning (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Failed to refresh the RT and cannot use existing AT (expired or missing).  
MSAL: Error (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - 49c19e9e-c30e-46e4-b021-3cd1ee658796] Exception type: Microsoft.Identity.Client.MsalUiRequiredException
, ErrorCode: invalid_grant
HTTP StatusCode 400
CorrelationId 49c19e9e-c30e-46e4-b021-3cd1ee658796

   at Microsoft.Identity.Client.OAuth2.OAuth2Client.ThrowServerException(HttpResponse response, RequestContext requestContext)
   at Microsoft.Identity.Client.OAuth2.OAuth2Client.CreateResponse[T](HttpResponse response, RequestContext requestContext)
   at Microsoft.Identity.Client.OAuth2.OAuth2Client.ExecuteRequestAsync[T](Uri endPoint, HttpMethod method, RequestContext requestContext, Boolean expectErrorsOn200OK, Boolean addCommonHeaders)
   at Microsoft.Identity.Client.OAuth2.OAuth2Client.GetTokenAsync(Uri endPoint, RequestContext requestContext, Boolean addCommonHeaders)
   at Microsoft.Identity.Client.OAuth2.TokenClient.SendHttpAndClearTelemetryAsync(String tokenEndpoint)
   at Microsoft.Identity.Client.OAuth2.TokenClient.SendHttpAndClearTelemetryAsync(String tokenEndpoint)
   at Microsoft.Identity.Client.OAuth2.TokenClient.SendTokenRequestAsync(IDictionary`2 additionalBodyParameters, String scopeOverride, String tokenEndpointOverride, CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.RequestBase.SendTokenRequestAsync(String tokenEndpoint, IDictionary`2 additionalBodyParameters, CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.Silent.CacheSilentStrategy.RefreshAccessTokenAsync(MsalRefreshTokenCacheItem msalRefreshTokenItem, CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.Silent.CacheSilentStrategy.RefreshRtOrFailAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.Silent.CacheSilentStrategy.ExecuteAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.Silent.CacheSilentStrategy.ExecuteAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.Silent.SilentRequest.ExecuteAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.Silent.SilentRequest.ExecuteAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.RequestBase.RunAsync(CancellationToken cancellationToken) 
Exception thrown: 'Microsoft.Identity.Client.MsalUiRequiredException' in System.Private.CoreLib.dll
MsalUiRequiredException: AADSTS50196: The server terminated an operation because it encountered a client request loop. Please contact your app vendor.
Trace ID: f2a8a395-8023-4786-9bae-9ba2f34c9100
Correlation ID: 49c19e9e-c30e-46e4-b021-3cd1ee658796
Timestamp: 2021-01-20 11:20:50Z
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] MSAL MSAL.UAP with assembly version '4.24.0.0'. CorrelationId(bfab291a-bb78-48f5-a6a1-e7dba26fc9fc) 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] === InteractiveParameters Data ===
LoginHint provided: False
User provided: False
UseEmbeddedWebView: NotSpecified
ExtraScopesToConsent: 
Prompt: not_specified
HasCustomWebUi: False

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] 
=== Request Data ===
Authority Provided? - True
Scopes - User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenInteractive
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc

MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] === Token Acquisition (InteractiveRequest) started:

    Authority Host: login.microsoftonline.com 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:48 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] Resolving authority endpoints... Already resolved? - FALSE 
MSAL: Info (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:52 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] Authorization result status returned user cancelled authentication.  
MSAL: Error (False) MSAL 4.24.0.0 MSAL.UAP N/A [01/20/2021 11:20:52 - bfab291a-bb78-48f5-a6a1-e7dba26fc9fc] Exception type: Microsoft.Identity.Client.MsalClientException
, ErrorCode: authentication_canceled

   at Microsoft.Identity.Client.Internal.AuthCodeRequestComponent.VerifyAuthorizationResult(AuthorizationResult authorizationResult, String originalState)
   at Microsoft.Identity.Client.Internal.AuthCodeRequestComponent.FetchAuthCodeAndPkceInternalAsync(IWebUI webUi, CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.AuthCodeRequestComponent.FetchAuthCodeAndPkceVerifierAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.InteractiveRequest.GetTokenResponseAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.InteractiveRequest.ExecuteAsync(CancellationToken cancellationToken)
   at Microsoft.Identity.Client.Internal.Requests.RequestBase.RunAsync(CancellationToken cancellationToken) 
Exception thrown: 'Microsoft.Identity.Client.MsalClientException' in System.Private.CoreLib.dll
Exception thrown: 'Microsoft.Identity.Client.MsalClientException' in System.Private.CoreLib.dll
Exception thrown: 'Microsoft.Graph.ServiceException' in System.Private.CoreLib.dll
Exception thrown: 'Microsoft.Graph.ServiceException' in System.Private.CoreLib.dll
Exception thrown: 'Microsoft.Graph.ServiceException' in System.Private.CoreLib.dll
Failed to check for files timer tick: Code: generalException
Message: An error occurred sending the request.

The thread 0x2758 has exited with code 0 (0x0).
The thread 0x4e88 has exited with code 0 (0x0).
The program '[21852] InkCalendar.exe' has exited with code 1 (0x1).
TheJoeFin picture TheJoeFin on 20 Jan 2021

Thanks, while I have an idea of what's going on, there isn't enough info in that log file to pinpoint the issue. The logs show that an access token exists in the cache, however AcquireTokenSilent does not seem to find it for some reason. There was some work related to scopes around MSAL 4.18 timeframe...

I can't repro the bug by the way :(

To proceed I'll need 2 things:

  • enable Verbose logging and also PII logging. Please send them via email if you have privacy concerns (bogavril @@ microsoft.com)
  • I'm adding more (verbose level) logging to MSAL around scopes. I'll produce a nuget package with it and you can try again. The package will be signed by Microsoft (instructions on how to use packages from a local folder here)

Does that sound ok?

bgavrilMS picture bgavrilMS on 20 Jan 2021

Sounds good to me, I'll try to get those logs this week and send them over to you.

TheJoeFin picture TheJoeFin on 20 Jan 2021

@TheJoeFin - I added more logging to MSAL and produced a package. Please note that the package is signed by Microsoft.

Microsoft.Identity.Client.4.25.1-internal.nupkg.zip

bgavrilMS picture bgavrilMS on 21 Jan 2021
👍1

Opps, GitHub closed the issue after I completed the PR that just adds more logging to MSAL.

Ok, so from the logs it looks like you are requesting scopes:
User.Read User.ReadBasic.All Calendars.Read Files.ReadWrite.AppFolder

And you are receiving scopes:
openid profile User.Read Calendars.Read Files.ReadWrite.AppFolder

openid and profile are actually also requested by MSAL, so that's ok. It looks like User.ReadBasic.All isn't returned at all. I will need to investigate this with the server, it looks like a bug on their side.

Still, you app seems to (mostly) function, so I wonder - do you actually need User.ReadBasic.All ?

bgavrilMS picture bgavrilMS on 25 Jan 2021

This SO post suggests that User.ReadBasic.All isn't granted for MSA / Microsoft accounts (i.e. @outlook.com, @live.com etc.)

https://stackoverflow.com/questions/50318929/user-readbasic-all-scope-not-granted-v2

bgavrilMS picture bgavrilMS on 25 Jan 2021

I believe that scope was added while I was trying to get the profile picture showing in the settings page, so I'll try removing all scopes except Files.ReadWrite.AppFolder and see if that fixes the looping bug.

TheJoeFin picture TheJoeFin on 25 Jan 2021

Yeah, I can repro this with an MSA user.

bgavrilMS picture bgavrilMS on 25 Jan 2021

That makes sense. I don't know the Graph API that well, but generally the delegated scopes that end in ".All" probably don't work with Microsoft users. AAD will not issue you a token that allows you to read the basic info of all Microsoft users :)

I'm just wondering how we can change MSAL to showcase this, the current experience, where you get looping errors, is bad - it's bad for you because you only discover it late and is bad for AAD because you inadvertently hammer it with requests.

bgavrilMS picture bgavrilMS on 25 Jan 2021
👍1

After reducing the scopes to just Files.ReadWrite.AppFolder this client request loop does not occur. (Tested using package 4.25)

Thank you for working on this. I don't know how to suggest to devs not to use the .all scopes, maybe add this to the getting started documentation or so throw some sort of error when the scopes are read.

TheJoeFin picture TheJoeFin on 26 Jan 2021

@jmprieur @henrik-me - any thoughts on how to handle this better? Some scopes, like User.ReadBasic.All are not issued by MSA.

We could throw an exception (this is what MSAL Android does) - although it'll be hard to create an app that needs User.ReadBasic.All
We could expose it as "declined scopes" (this is what C++ does) to better inform the user. Not a breaking change.

bgavrilMS picture bgavrilMS on 26 Jan 2021
Was this page helpful?
0 / 5 - 0 ratings

Related issues

crmann1 picture crmann1  Â·  5Comments
trwalke picture trwalke  Â·  4Comments
chrisevans9629 picture chrisevans9629  Â·  5Comments
msminski picture msminski  Â·  6Comments
saketkataruka picture saketkataruka  Â·  5Comments