search

AzureAD / microsoft-authentication-library-for-dotnet

Microsoft Authentication Library (MSAL) for .NET
https://aka.ms/msal-net
MIT License
1.39k stars 340 forks source link

[Bug] obo_cache_key_not_in_cache_error with SQL DistributedTokenCache #3808

Closed zmarkusdev closed 1 year ago

zmarkusdev commented 1 year ago

Logs and network traces Without logs or traces, it is unlikely that the team can investigate your issue. Capturing logs and network traces is described in Logging wiki.

2022-11-15 15:16:01,284 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z] [Internal cache] Clearing user token cache accessor.
2022-11-15 15:16:01,284 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z - 3a69b238-071c-4d69-9f1f-9c85d0203447] [Internal cache] Total number of cache partitions found while getting access tokens: 0
2022-11-15 15:16:01,284 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z - 3a69b238-071c-4d69-9f1f-9c85d0203447] [FindAccessTokenAsync] Discovered 0 access tokens in cache using partition key: ************
2022-11-15 15:16:01,284 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z] [Internal cache] Total number of cache partitions found while getting refresh tokens: 0
2022-11-15 15:16:01,300 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z - 3a69b238-071c-4d69-9f1f-9c85d0203447] [FindRefreshTokenAsync] Discovered 0 refresh tokens in cache using key: ************
2022-11-15 15:16:01,300 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z - 3a69b238-071c-4d69-9f1f-9c85d0203447] [OBO request] AcquireTokenInLongRunningProcess was called and no access or refresh tokens were found in the cache.
2022-11-15 15:16:01,300 [46] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - MSAL Logging: False MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-15 14:16:01Z - 3a69b238-071c-4d69-9f1f-9c85d0203447] Exception type: Microsoft.Identity.Client.MsalClientException
, ErrorCode: obo_cache_key_not_in_cache_error

   at Microsoft.Identity.Client.Internal.Requests.OnBehalfOfRequest.<RefreshRtOrFetchNewAccessTokenAsync>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Identity.Client.Internal.Requests.OnBehalfOfRequest.<ExecuteAsync>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Identity.Client.Internal.Requests.RequestBase.<RunAsync>d__12.MoveNext()

Which version of MSAL.NET are you using? MSAL.NET 4.47.2.0

Platform .NET 4.6.1

What authentication flow has the issue?

Other?

Is this a new or existing app?

b. The app is in production, I haven't upgraded MSAL, but started seeing this issue.

Repro

var msalConfig = DbContext.msalConfiguration.FirstOrDefault(mc => mc.idMsalConfiguration == connectionInfo.SmtpAuthMode);
smtpClient = new MailKit.Net.Smtp.SmtpClient();
smtpClient.Connect(connectionInfo.SystemMessageServerIp, connectionInfo.SystemMessageServerPort, connectionInfo.SystemMessageUseSsl);

var scopes = new[] 
{
    "email",
    "offline_access",
    "https://outlook.office.com/IMAP.AccessAsUser.All", // Only needed for IMAP
    //"https://outlook.office.com/POP.AccessAsUser.All",  // Only needed for POP
    "https://outlook.office.com/SMTP.Send", // Only needed for SMTP
};

var app = ConfidentialClientApplicationBuilder.CreateWithApplicationOptions(new ConfidentialClientApplicationOptions
{
    ClientId = msalConfig.backendClientId,
    ClientSecret = msalConfig.backendClientSecret,
    RedirectUri = msalConfig.backendRedirectUri,
    AadAuthorityAudience = AadAuthorityAudience.AzureAdAndPersonalMicrosoftAccount
}).WithAuthority("https://login.microsoftonline.com/common")
    .WithLogging((level, message, containsPii) =>
    {
        Log.Debug($"MSAL Logging: {message}");
    }).Build();

app.AddDistributedTokenCache(services =>
{
    services.AddDistributedSqlServerCache(options =>
    {
        // Requires to reference Microsoft.Extensions.Caching.SqlServer
        options.ConnectionString = msalConfig.backendCacheConnectionString;
        options.SchemaName = msalConfig.backendCacheSchemaName;
        options.TableName = msalConfig.backendCacheTableName;

        // You don't want the SQL token cache to be purged before the access token has expired. Usually
        // access tokens expire after 1 hour (but this can be changed by token lifetime policies), whereas
        // the default sliding expiration for the distributed SQL database is 20 mins. 
        // Use a value above 60 mins (or the lifetime of a token in case of longer-lived tokens)
        options.DefaultSlidingExpiration = TimeSpan.FromHours(24);
    });
});

Log.Info("Current SmtpMsalSessionKey: " + connectionInfo.SmtpMsalSessionKey);

AuthenticationResult result = null;
try
{
    result = ((ILongRunningWebApi)app).AcquireTokenInLongRunningProcess(scopes, connectionInfo.SmtpMsalSessionKey).ExecuteAsync().Result;
}
catch (AggregateException e)
{
    if (e.InnerException is MsalClientException ie)
    {
        Log.Warn("Error while acquireing token in long running process", ie);

        string sessionkey = connectionInfo.SmtpMsalSessionKey;
        Log.Info("session key before: " + sessionkey);
        result = ((ILongRunningWebApi)app).InitiateLongRunningProcessInWebApi(scopes, connectionInfo.SmtpMsalSessionUserToken, ref sessionkey).ExecuteAsync().Result;
        Log.Info("session key after: " + sessionkey);
    }
}

if (result == null) throw new Exception("Result not fetched, login failed");

enforceSendMailAddress = result.Account.Username;

var oauth2 = new SaslMechanismOAuth2 (result.Account.Username, result.AccessToken);

smtpClient.Authenticate(oauth2);

Expected behavior Using the OBO key acquired by my web application in another console application should work with the same database cache.

Actual behavior I got the session key with AcquireTokenInLongRunningProcess in my web application and tried to use it in a background worker service (Console Application) to authenticate and send mails on behalf of the user. The log file reports, that the key cannot be found in the database cache, but the key is there and the connection string is the same as in the web application.

It works for a few days, if i refresh the key in the AggregateException handler. This code was added during troubleshooting of the problem.

Possible solution

Additional context / logs / screenshots / links to code

gerrit-amagno commented 1 year ago

Did you check the behaviour with 4.48? See #3736 for more information.

bgavrilMS commented 1 year ago

I don't think we made any changes in 4.48 related to OBO

bgavrilMS commented 1 year ago

@pmaytak - can you provide an opinion on this one please?

gerrit-amagno commented 1 year ago

Okay, I thought the changes in IByRefreshToken would also affect the OBO flow.

pmaytak commented 1 year ago

@zmarkusdev Can you provide Verbose MSAL logs for one of those failed requests?

I immediately don't see anything that may cause this behavior, so would need to look at detailed logs step-by-step. Based on those basic logs, it seems like no tokens are even loaded into MSAL from the distributed cache for that cache key.

The cache key mentioned in the MSAL logs above is the same as the session key that you pass into the method, and same as the cache key in the SQL cache, right?

Do I understand this - it works initially in the console app when you call AcquireToken, but then throws an error, even though the same session key is used, and the record is in the cache?

zmarkusdev commented 1 year ago

The cache key mentioned in the MSAL logs above is the same as the session key that you pass into the method, and same as the cache key in the SQL cache, right?

Yes it is the same I got during the authentication dialog.

Do I understand this - it works initially in the console app when you call AcquireToken, but then throws an error, even though the same session key is used, and the record is in the cache?

Exactly, I have the exact key in the database and it won't find it unfortunately, this is why I built in this additional Acquire.

Here are the verbose logs, I hope you can work with this? Let me know if you need any more informations, thanks!

2022-11-29 08:07:01,301 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] ConfidentialClientApplication 57631121 created
2022-11-29 08:07:01,304 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] MSAL MSAL.Desktop with assembly version '4.47.2.0'. CorrelationId(b05c521d-9532-49c7-aa28-ad2e1d295c19)
2022-11-29 08:07:01,305 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] === OnBehalfOfParameters ===
SendX5C: False
ForceRefresh: False
UserAssertion set: False
LongRunningOboCacheKey set: True

2022-11-29 08:07:01,307 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] 
=== Request Data ===
Authority Provided? - True
Client Id - e15e213f-59a1-49c9-bf0a-3cfa15125ab5
Scopes - email offline_access https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send
Redirect Uri - https://login.microsoftonline.com/common/oauth2/nativeclient
Extra Query Params Keys (space separated) - 
ClaimsAndClientCapabilities - 
Authority - https://login.microsoftonline.com/common/
ApiId - AcquireTokenOnBehalfOf
IsConfidentialClient - True
SendX5C - False
LoginHint - 
IsBrokerConfigured - False
HomeAccountId - 
CorrelationId - b05c521d-9532-49c7-aa28-ad2e1d295c19
UserAssertion set: False
LongRunningOboCacheKey set: True
Region configured: 

2022-11-29 08:07:01,308 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] === Token Acquisition (OnBehalfOfRequest) started:
    Authority: https://login.microsoftonline.com/common/
    Scope: email offline_access https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send
    ClientId: e15e213f-59a1-49c9-bf0a-3cfa15125ab5

2022-11-29 08:07:01,309 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Region discovery] Not using a regional authority. 
2022-11-29 08:07:01,310 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Instance Discovery] Tried to use network cache provider for login.microsoftonline.com. Success? True. 
2022-11-29 08:07:01,311 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Instance Discovery] The network provider found an entry for login.microsoftonline.com. 
2022-11-29 08:07:01,312 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] Starting [OBO Request] Looking in the cache for an access token
2022-11-29 08:07:01,312 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Cache Session Manager] Entering the cache semaphore. Real semaphore: False. Count: 1
2022-11-29 08:07:01,313 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Cache Session Manager] Entered cache semaphore
2022-11-29 08:07:01,321 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Clearing user token cache accessor.
2022-11-29 08:07:01,322 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Cache Session Manager] Released cache semaphore
2022-11-29 08:07:01,322 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [Internal cache] Total number of cache partitions found while getting access tokens: 0
2022-11-29 08:07:01,323 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [FindAccessTokenAsync] Discovered 0 access tokens in cache using partition key: h4hEBJud1XSXw1cbekpjIJCgHFMN8RkJkNaBuooxrIc
2022-11-29 08:07:01,323 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [FindAccessTokenAsync] No access tokens found in the cache. Skipping filtering. 
2022-11-29 08:07:01,324 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] Finished [OBO Request] Looking in the cache for an access token in 12 ms
2022-11-29 08:07:01,326 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [OBO request] Long-running OBO flow, trying to refresh using an refresh token flow.
2022-11-29 08:07:01,327 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting refresh tokens: 0
2022-11-29 08:07:01,329 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [FindRefreshTokenAsync] Discovered 0 refresh tokens in cache using key: h4hEBJud1XSXw1cbekpjIJCgHFMN8RkJkNaBuooxrIc
2022-11-29 08:07:01,330 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [FindRefreshTokenAsync] No RTs found in the MSAL cache 
2022-11-29 08:07:01,332 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [FindRefreshTokenAsync] Checking ADAL cache for matching RT. 
2022-11-29 08:07:01,332 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] IsLegacyAdalCacheEnabled: yes
2022-11-29 08:07:01,333 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] [OBO request] AcquireTokenInLongRunningProcess was called and no access or refresh tokens were found in the cache.
2022-11-29 08:07:01,333 [78] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - b05c521d-9532-49c7-aa28-ad2e1d295c19] MSAL.Desktop.4.47.2.0.MsalClientException: 
    ErrorCode: obo_cache_key_not_in_cache_error
Microsoft.Identity.Client.MsalClientException: The token cache does not contain a token with an OBO cache key that matches the longRunningProcessSessionKey passed into ILongRunningWebApi.AcquireTokenInLongRunningProcess method. Call ILongRunningWebApi.InitiateLongRunningProcessInWebApi method with this longRunningProcessSessionKey first or call ILongRunningWebApi.AcquireTokenInLongRunningProcess method with an already used longRunningProcessSessionKey. See https://aka.ms/msal-net-long-running-obo .
   at Microsoft.Identity.Client.Internal.Requests.OnBehalfOfRequest.<RefreshRtOrFetchNewAccessTokenAsync>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Identity.Client.Internal.Requests.OnBehalfOfRequest.<ExecuteAsync>d__3.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Identity.Client.Internal.Requests.RequestBase.<RunAsync>d__12.MoveNext()
2022-11-29 08:07:01,336 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] MSAL MSAL.Desktop with assembly version '4.47.2.0'. CorrelationId(034e5207-70f0-4a80-8ef7-7666089cdeff)
2022-11-29 08:07:01,336 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] === OnBehalfOfParameters ===
SendX5C: False
ForceRefresh: False
UserAssertion set: True
LongRunningOboCacheKey set: True

2022-11-29 08:07:01,337 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] 
=== Request Data ===
Authority Provided? - True
Client Id - e15e213f-59a1-49c9-bf0a-3cfa15125ab5
Scopes - email offline_access https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send
Redirect Uri - https://login.microsoftonline.com/common/oauth2/nativeclient
Extra Query Params Keys (space separated) - 
ClaimsAndClientCapabilities - 
Authority - https://login.microsoftonline.com/common/
ApiId - AcquireTokenOnBehalfOf
IsConfidentialClient - True
SendX5C - False
LoginHint - 
IsBrokerConfigured - False
HomeAccountId - 
CorrelationId - 034e5207-70f0-4a80-8ef7-7666089cdeff
UserAssertion set: True
LongRunningOboCacheKey set: True
Region configured: 

2022-11-29 08:07:01,337 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] === Token Acquisition (OnBehalfOfRequest) started:
    Authority: https://login.microsoftonline.com/common/
    Scope: email offline_access https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send
    ClientId: e15e213f-59a1-49c9-bf0a-3cfa15125ab5

2022-11-29 08:07:01,338 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Region discovery] Not using a regional authority. 
2022-11-29 08:07:01,339 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Instance Discovery] Tried to use network cache provider for login.microsoftonline.com. Success? True. 
2022-11-29 08:07:01,340 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Instance Discovery] The network provider found an entry for login.microsoftonline.com. 
2022-11-29 08:07:01,340 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Starting [OBO Request] Looking in the cache for an access token
2022-11-29 08:07:01,341 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Cache Session Manager] Entering the cache semaphore. Real semaphore: False. Count: 1
2022-11-29 08:07:01,341 [73] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Cache Session Manager] Entered cache semaphore
2022-11-29 08:07:01,342 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Clearing user token cache accessor.
2022-11-29 08:07:01,342 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Cache Session Manager] Released cache semaphore
2022-11-29 08:07:01,343 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Internal cache] Total number of cache partitions found while getting access tokens: 0
2022-11-29 08:07:01,343 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [FindAccessTokenAsync] Discovered 0 access tokens in cache using partition key: h4hEBJud1XSXw1cbekpjIJCgHFMN8RkJkNaBuooxrIc
2022-11-29 08:07:01,343 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [FindAccessTokenAsync] No access tokens found in the cache. Skipping filtering. 
2022-11-29 08:07:01,344 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Finished [OBO Request] Looking in the cache for an access token in 3 ms
2022-11-29 08:07:01,344 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [OBO request] Long-running OBO flow, trying to refresh using an refresh token flow.
2022-11-29 08:07:01,344 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting refresh tokens: 0
2022-11-29 08:07:01,345 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [FindRefreshTokenAsync] Discovered 0 refresh tokens in cache using key: h4hEBJud1XSXw1cbekpjIJCgHFMN8RkJkNaBuooxrIc
2022-11-29 08:07:01,345 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [FindRefreshTokenAsync] No RTs found in the MSAL cache 
2022-11-29 08:07:01,346 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [FindRefreshTokenAsync] Checking ADAL cache for matching RT. 
2022-11-29 08:07:01,346 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] IsLegacyAdalCacheEnabled: yes
2022-11-29 08:07:01,346 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [OBO request] No Refresh Token was found in the cache. Fetching OBO token from ESTS
2022-11-29 08:07:01,347 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Starting TokenClient:SendTokenRequestAsync
2022-11-29 08:07:01,354 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [TokenClient] Before adding the client assertion / secret
2022-11-29 08:07:01,355 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [TokenClient] After adding the client assertion / secret
2022-11-29 08:07:01,355 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Token Client] Fetching MsalTokenResponse .... 
2022-11-29 08:07:01,356 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Starting [Oauth2Client] Sending POST request 
2022-11-29 08:07:01,356 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Starting [HttpManager] ExecuteAsync
2022-11-29 08:07:01,357 [67] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [HttpManager] Sending request. Method: POST. URI: https://login.microsoftonline.com/common/oauth2/v2.0/token. 
2022-11-29 08:07:01,846 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [HttpManager] Received response. Status code: OK. 
2022-11-29 08:07:01,848 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Finished [HttpManager] ExecuteAsync in 492 ms
2022-11-29 08:07:01,849 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Finished [Oauth2Client] Sending POST request  in 493 ms
2022-11-29 08:07:01,851 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Starting [OAuth2Client] Deserializing response
2022-11-29 08:07:01,852 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Finished [OAuth2Client] Deserializing response in 1 ms
2022-11-29 08:07:01,853 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Finished TokenClient:SendTokenRequestAsync in 506 ms
2022-11-29 08:07:01,854 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Checking client info returned from the server..
2022-11-29 08:07:01,855 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Saving token response to cache..
2022-11-29 08:07:01,855 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] 
[MsalTokenResponse]
Error: 
ErrorDescription: 
Scopes: https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send https://outlook.office.com/User.Read 
ExpiresIn: 4386
RefreshIn: 
AccessToken returned: True
AccessToken Type: Bearer
RefreshToken returned: True
IdToken returned: True
ClientInfo: eyJ1aWQiOiJkNjg3ZWU3Ny0yNWI5LTQ3ZDMtYjRkOC04NzM4MDg3Y2MwOGIiLCJ1dGlkIjoiMmFlOWZhYzQtZTRjNC00ZDdiLWE4NTktM2VjMWE3MDE2NjUxIn0
FamilyId: 
WamAccountId exists: False

2022-11-29 08:07:01,856 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Region discovery] Not using a regional authority. 
2022-11-29 08:07:01,856 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [Instance Discovery] Tried to use network cache provider for login.microsoftonline.com. Success? True. 
2022-11-29 08:07:01,857 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [SaveTokenResponseAsync] Entering token cache semaphore. Count Real semaphore: False. Count: 1.
2022-11-29 08:07:01,858 [68] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [SaveTokenResponseAsync] Entered token cache semaphore. 
2022-11-29 08:07:01,859 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Clearing user token cache accessor.
2022-11-29 08:07:01,859 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [SaveTokenResponseAsync] Saving AT in cache and removing overlapping ATs...
2022-11-29 08:07:01,860 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Looking for scopes for the authority in the cache which intersect with email offline_access https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send
2022-11-29 08:07:01,860 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting access tokens: 0
2022-11-29 08:07:01,860 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Intersecting scope entries count - 0
2022-11-29 08:07:01,861 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Matching entries after filtering by user - 0
2022-11-29 08:07:01,861 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [SaveTokenResponseAsync] Saving Id Token and Account in cache ...
2022-11-29 08:07:01,861 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [SaveTokenResponseAsync] Saving RT in cache...
2022-11-29 08:07:01,861 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] IsLegacyAdalCacheEnabled: yes
2022-11-29 08:07:01,862 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [AdalCacheOperations] Serializing token cache with 1 items. 
2022-11-29 08:07:01,862 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting refresh tokens: 1
2022-11-29 08:07:01,863 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting access tokens: 1
2022-11-29 08:07:01,863 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting refresh tokens: 1
2022-11-29 08:07:01,864 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting access tokens: 1
2022-11-29 08:07:01,864 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z] [Internal cache] Total number of cache partitions found while getting refresh tokens: 1
2022-11-29 08:07:01,865 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Total number of access tokens in cache: 1
Total number of refresh tokens in cache: 1
Token cache dump of the first 1 cache keys.
AT Cache Key: d687ee77-25b9-47d3-b4d8-8738087cc08b.2ae9fac4-e4c4-4d7b-a859-3ec1a7016651-login.windows.net-accesstoken-e15e213f-59a1-49c9-bf0a-3cfa15125ab5-2ae9fac4-e4c4-4d7b-a859-3ec1a7016651-https://outlook.office.com/imap.accessasuser.all https://outlook.office.com/smtp.send https://outlook.office.com/user.read

2022-11-29 08:07:01,865 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [SaveTokenResponseAsync] Released token cache semaphore. 
2022-11-29 08:07:01,865 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] 
    === Token Acquisition finished successfully:
2022-11-29 08:07:01,871 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff]  AT expiration time: 29.11.2022 08:20:07 +00:00, scopes: https://outlook.office.com/IMAP.AccessAsUser.All https://outlook.office.com/SMTP.Send https://outlook.office.com/User.Read. source: IdentityProvider
2022-11-29 08:07:01,871 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] Fetched access token from host login.microsoftonline.com. Endpoint: https://login.microsoftonline.com/common/. 
2022-11-29 08:07:01,871 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] 
[LogMetricsFromAuthResult] Cache Refresh Reason: NoCachedAccessToken
[LogMetricsFromAuthResult] DurationInCacheInMs: 1
[LogMetricsFromAuthResult] DurationTotalInMs: 534
[LogMetricsFromAuthResult] DurationInHttpInMs: 488

2022-11-29 08:07:01,872 [79] DEBUG notifications.EMailBaseQueue [(null)] - (Log) - PII:True MSAL 4.47.2.0 MSAL.Desktop 4.8 or later Windows Server 2022 Standard [2022-11-29 07:07:01Z - 034e5207-70f0-4a80-8ef7-7666089cdeff] [LogMetricsFromAuthResult] TokenEndpoint: https://login.microsoftonline.com/common/oauth2/v2.0/token
zmarkusdev commented 1 year ago

Any news regarding this problem, do you need any more informations or log outputs from this issue? Thanks!

pmaytak commented 1 year ago

We had a user report a similar behavior to this - also with SQL distributed cache, on .NET Fx runtime. Seems like the SQL client when retrieving data was throwing an exception which was swallowed, and MSAL perhaps got an empty result set. Can you try to get debug logs for the token cache. You can also set OnL2CacheFailure to retry the L2 call and/or add extra logs.

pmaytak commented 1 year ago

We had a user report a similar behavior to this - also with SQL distributed cache, on .NET Fx runtime. Seems like the SQL client when retrieving data was throwing an exception which was swallowed, and MSAL perhaps got an empty result set. Can you try to get debug logs for the token cache. You can also set OnL2CacheFailure to retry the L2 call and/or add extra logs.

@zmarkusdev Did you have a chance to try the above: extra logs and OnL2CacheFailure?

zmarkusdev commented 1 year ago

Sorry for the late reply, I will check this 2 things this week and will deliver you more informations for troubleshooting. Thanks!

zmarkusdev commented 1 year ago

Hello! After deploying the logging change to the environment where this problem occurs, I get the following error message OnL2CacheFailure:

System.TypeInitializationException: The type initializer for 'Microsoft.Data.SqlClient.TdsParser' threw an exception. ---> System.TypeInitializationException: The type initializer for 'Microsoft.Data.SqlClient.SNILoadHandle' threw an exception. ---> System.TypeInitializationException: The type initializer for 'Microsoft.Data.SqlClient.SNINativeMethodWrapper' threw an exception. ---> System.ComponentModel.Win32Exception: Failed to load C:\Program Files\service\x64\SNI.dll
   at Microsoft.Data.SqlClient.SNINativeMethodWrapper..cctor() in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\Interop\SNINativeMethodWrapper.cs:line 66
   --- End of inner exception stack trace ---
   at Microsoft.Data.SqlClient.SNINativeMethodWrapper.SNIInitialize()
   at Microsoft.Data.SqlClient.SNILoadHandle..ctor() in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserSafeHandles.cs:line 31
   at Microsoft.Data.SqlClient.SNILoadHandle..cctor() in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParserSafeHandles.cs:line 16
   --- End of inner exception stack trace ---
   at Microsoft.Data.SqlClient.TdsParser..cctor() in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 156
   --- End of inner exception stack trace ---
   at Microsoft.Data.SqlClient.TdsParser..ctor(Boolean MARS, Boolean fAsynchronous) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 32
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.LoginNoFailover(ServerInfo serverInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString connectionOptions, SqlCredential credential, TimeoutTimer timeout) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlInternalConnectionTds.cs:line 1548
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds.OpenLoginEnlist(TimeoutTimer timeout, SqlConnectionString connectionOptions, SqlCredential credential, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlInternalConnectionTds.cs:line 1442
   at Microsoft.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, ServerCertificateValidationCallback serverCallback, ClientCertificateRetrievalCallback clientCallback, DbConnectionPool pool, String accessToken, SqlClientOriginalNetworkAddressInfo originalNetworkAddressInfo, Boolean applyTransientFaultHandling, SqlAuthenticationProviderManager sqlAuthProviderManager) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlInternalConnectionTds.cs:line 425
   at Microsoft.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlConnectionFactory.cs:line 123
   at Microsoft.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\ProviderBase\DbConnectionFactory.cs:line 143
   at Microsoft.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\ProviderBase\DbConnectionPool.cs:line 870
   at Microsoft.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\ProviderBase\DbConnectionPool.cs:line 1807
   at Microsoft.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection) in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\ProviderBase\DbConnectionPool.cs:line 1293
   at Microsoft.Data.ProviderBase.DbConnectionPool.WaitForPendingOpen() in E:\agent1\_work\31\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\ProviderBase\DbConnectionPool.cs:line 1121
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Extensions.Caching.SqlServer.DatabaseOperations.<GetCacheItemAsync>d__28.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Extensions.Caching.SqlServer.DatabaseOperations.<GetCacheItemAsync>d__21.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Extensions.Caching.SqlServer.SqlServerCache.<GetAsync>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.Identity.Web.TokenCacheProviders.Distributed.MsalDistributedTokenCacheAdapter.<L2OperationWithRetryOnFailureAsync>d__17.MoveNext()

Any solutions for this problem? The service is running with a user, that has access to the specified location.

pmaytak commented 1 year ago

This error doesn't come from MSAL. One of the users came across a very similar error and they fixed it by explicitly referencing Microsoft.Data.SQLClient 2.0.1 and Microsoft.Data.SQLClient.SNI 2.0.1. You can also try updating to the latest version possible. They also made sure the connection string contains TrustServerCertificate=true. Another thing to try is to update Microsoft.Extensions.Caching.SqlServer package to the latest.

zmarkusdev commented 1 year ago

Documentation of my troubleshooting steps as per your recommendations:

  1. Changed the connection string with TrustServerCertificate=true - same exception
  2. Updated Microsoft.Extensions.Caching.SqlServer to 6.0.13 - same exception
  3. Add explicit reference to Microsoft.Data.SQLClient 2.0.1 and Microsoft.Data.SQLClient.SNI 2.0.1 - works

Thanks for your help, we were able to fix this problem!