[Bug] obo_cache_key_not_in_cache_error with SQL DistributedTokenCache #3808

zmarkusdev · 2022-11-15T14:31:18Z

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?

Desktop / Mobile
- Interactive
- Integrated Windows Authentication
- Username Password
- Device code flow (browserless)
Web app
- Authorization code
- [*] On-Behalf-Of
Daemon app
- Service to Service calls

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

The text was updated successfully, but these errors were encountered:

gerrit-amagno · 2022-11-22T12:21:14Z

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

bgavrilMS · 2022-11-22T15:22:53Z

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

bgavrilMS · 2022-11-22T15:23:49Z

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

gerrit-amagno · 2022-11-22T15:45:12Z

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

pmaytak · 2022-11-23T03:14:54Z

@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 · 2022-11-29T07:14:19Z

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 · 2023-01-09T05:49:08Z

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

pmaytak · 2023-01-10T21:50:03Z

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 · 2023-01-18T21:48:42Z

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 · 2023-01-23T09:47:49Z

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

zmarkusdev · 2023-01-30T07:03:40Z

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 · 2023-01-31T04:06:35Z

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 · 2023-02-06T07:09:14Z

Documentation of my troubleshooting steps as per your recommendations:

Changed the connection string with TrustServerCertificate=true - same exception
Updated Microsoft.Extensions.Caching.SqlServer to 6.0.13 - same exception
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!

pmaytak added the long-running-obo label Nov 23, 2022

bgavrilMS added bug P2 labels Dec 21, 2022

bgavrilMS added this to MSAL Customer Trust / QM Dec 21, 2022

bgavrilMS moved this to Triage in MSAL Customer Trust / QM Dec 21, 2022

bgavrilMS added the scenario:WebApi label Dec 22, 2022

pmaytak self-assigned this Jan 10, 2023

pmaytak moved this from Triage to In Progress in MSAL Customer Trust / QM Jan 10, 2023

pmaytak moved this from In Progress to Blocked/Waiting for reply in MSAL Customer Trust / QM Jan 28, 2023

pmaytak added the external label Jan 31, 2023

pmaytak added this to the 4.50.0 milestone Jan 31, 2023

zmarkusdev closed this as completed Feb 6, 2023

github-project-automation bot moved this from Blocked/Waiting for reply to Fixed in MSAL Customer Trust / QM Feb 6, 2023

pmaytak mentioned this issue Feb 25, 2023

[Feature Request] Make L2 cache operation failures non-silent (throw an exception) AzureAD/microsoft-identity-web#2086

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Bug] obo_cache_key_not_in_cache_error with SQL DistributedTokenCache #3808

[Bug] obo_cache_key_not_in_cache_error with SQL DistributedTokenCache #3808

zmarkusdev commented Nov 15, 2022

gerrit-amagno commented Nov 22, 2022

bgavrilMS commented Nov 22, 2022

bgavrilMS commented Nov 22, 2022

gerrit-amagno commented Nov 22, 2022

pmaytak commented Nov 23, 2022

zmarkusdev commented Nov 29, 2022

zmarkusdev commented Jan 9, 2023

pmaytak commented Jan 10, 2023

pmaytak commented Jan 18, 2023

zmarkusdev commented Jan 23, 2023

zmarkusdev commented Jan 30, 2023

pmaytak commented Jan 31, 2023

zmarkusdev commented Feb 6, 2023

[Bug] obo_cache_key_not_in_cache_error with SQL DistributedTokenCache #3808

[Bug] obo_cache_key_not_in_cache_error with SQL DistributedTokenCache #3808

Comments

zmarkusdev commented Nov 15, 2022

Possible solution

Additional context / logs / screenshots / links to code

gerrit-amagno commented Nov 22, 2022

bgavrilMS commented Nov 22, 2022

bgavrilMS commented Nov 22, 2022

gerrit-amagno commented Nov 22, 2022

pmaytak commented Nov 23, 2022

zmarkusdev commented Nov 29, 2022

zmarkusdev commented Jan 9, 2023

pmaytak commented Jan 10, 2023

pmaytak commented Jan 18, 2023

zmarkusdev commented Jan 23, 2023

zmarkusdev commented Jan 30, 2023

pmaytak commented Jan 31, 2023

zmarkusdev commented Feb 6, 2023