Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Driver sending expired token intermittently during Azure login #2238

Closed
cheenamalhotra opened this issue Nov 22, 2023 · 4 comments · Fixed by #2273
Closed

Driver sending expired token intermittently during Azure login #2238

cheenamalhotra opened this issue Nov 22, 2023 · 4 comments · Fixed by #2273

Comments

@cheenamalhotra
Copy link
Member

cheenamalhotra commented Nov 22, 2023 •
edited
Loading

Describe the bug

Intermittently received error Login failed for user '<token-identified principal>. The same user can login with the same token again.

I think what's happening is that while MSAL is working on renewing access token, ActiveDirectoryAuthenticationTimeoutRetryHelper is picking up an expired token it finds in cache.

I gathered log here that may be helpful to figure out what's acting in between:

Expand for logs (for error scenario) 
23-11-22 10:15:43.1122670 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) 
=== Request Data ===
Authority Provided? - True
Scopes - https://database.windows.net//.default
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - a4699e40-2861-4391-96f4-2dc8b90f595c
UserAssertion set: False
LongRunningOboCacheKey set: False
Region configured: 

23-11-22 10:15:43.1122750 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) === Token Acquisition (SilentRequest) started:
	 Scopes: https://database.windows.net//.default
	Authority Host: login.windows.net
23-11-22 10:15:43.1123000 pid:90929 tid:14 sqltools Verbose: 0 : Before cache access, acquiring lock for token cache
23-11-22 10:15:43.1125960 pid:90929 tid:14 sqltools Verbose: 0 : Before access, the store has changed
23-11-22 10:15:43.1128750 pid:90929 tid:14 sqltools Verbose: 0 : Read '59536' bytes from storage
23-11-22 10:15:43.1128810 pid:90929 tid:14 sqltools Verbose: 0 : Deserializing the store
23-11-22 10:15:43.1176570 pid:90929 tid:14 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z] (azuredatastudio: 0.0.0.0) [Internal cache] Clearing user token cache accessor.
23-11-22 10:15:43.1176870 pid:90929 tid:14 sqltools Verbose: 0 : After access
23-11-22 10:15:43.1179440 pid:90929 tid:14 sqltools Information: 0 : Released local lock
23-11-22 10:15:43.1179600 pid:90929 tid:14 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting access tokens: 2
23-11-22 10:15:43.1179690 pid:90929 tid:14 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [FindAccessTokenAsync] Discovered 9 access tokens in cache using partition key: 3e7d7b79-6622-4a75-b22f-d5db22b6978c.72f988bf-86f1-41af-91ab-2d7cd011db47
23-11-22 10:15:43.1179840 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:43.1180050 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Access token has expired or about to expire. [Current time (11/22/2023 18:15:43) - Expiration Time (11/17/2023 22:47:15 +00:00) - Extended Expiration Time (11/17/2023 22:47:15 +00:00)]
23-11-22 10:15:43.1180270 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:43.1180460 pid:90929 tid:14 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting refresh tokens: 2
23-11-22 10:15:43.1180530 pid:90929 tid:14 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [FindRefreshTokenAsync] Discovered 1 refresh tokens in cache using key: 3e7d7b79-6622-4a75-b22f-d5db22b6978c.72f988bf-86f1-41af-91ab-2d7cd011db47
23-11-22 10:15:43.1180580 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:43.1180730 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [FindRefreshTokenAsync] Refresh token found in the cache? - True
23-11-22 10:15:43.1180830 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Instance Discovery] Instance discovery is enabled and will be performed
23-11-22 10:15:43.1180870 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:43.1181160 pid:90929 tid:14 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Fetching instance discovery from the network from host login.windows.net. 
23-11-22 10:15:43.5414080 pid:90929 tid:11 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Authority validation enabled? True. 
23-11-22 10:15:43.5414730 pid:90929 tid:11 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:43Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Authority validation - is known env? True. 
23-11-22 10:15:44.2923360 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Checking client info returned from the server..
23-11-22 10:15:44.2934510 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Saving token response to cache..
23-11-22 10:15:44.3210360 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:44.3210850 pid:90929 tid:15 sqltools Verbose: 0 : Before cache access, acquiring lock for token cache
23-11-22 10:15:44.3215350 pid:90929 tid:15 sqltools Verbose: 0 : Before access, the store has changed
23-11-22 10:15:44.3217310 pid:90929 tid:15 sqltools Verbose: 0 : Read '59536' bytes from storage
23-11-22 10:15:44.3217360 pid:90929 tid:15 sqltools Verbose: 0 : Deserializing the store
23-11-22 10:15:44.3220890 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Clearing user token cache accessor.
23-11-22 10:15:44.3223570 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) [SaveTokenResponseAsync] Saving AT in cache and removing overlapping ATs...
23-11-22 10:15:44.3226700 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Looking for scopes for the authority in the cache which intersect with https://database.windows.net//.default
23-11-22 10:15:44.3226930 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting access tokens: 2
23-11-22 10:15:44.3227340 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Intersecting scope entries count - 1
23-11-22 10:15:44.3227710 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Matching entries after filtering by user - 1
23-11-22 10:15:44.3228620 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) [SaveTokenResponseAsync] Saving Id Token and Account in cache ...
23-11-22 10:15:44.3231170 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) [SaveTokenResponseAsync] Saving RT in cache...
23-11-22 10:15:44.3233110 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) IsLegacyAdalCacheEnabled: yes
23-11-22 10:15:44.3239130 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) [AdalCacheOperations] Serializing token cache with 1 items. 
23-11-22 10:15:44.3296900 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting refresh tokens: 2
23-11-22 10:15:44.3297100 pid:90929 tid:15 sqltools Verbose: 0 : After access
23-11-22 10:15:44.3297140 pid:90929 tid:15 sqltools Verbose: 0 : After access, cache in memory HasChanged
23-11-22 10:15:44.3299420 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting access tokens: 2
23-11-22 10:15:44.3300240 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting refresh tokens: 2
23-11-22 10:15:44.3314510 pid:90929 tid:15 sqltools Verbose: 0 : Serializing '50207' bytes
23-11-22 10:15:44.3323170 pid:90929 tid:15 sqltools Information: 0 : Released local lock
23-11-22 10:15:44.3340930 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) 
	=== Token Acquisition finished successfully:
23-11-22 10:15:44.3343950 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0)  AT expiration time: 2023-11-22 7:24:05PM +00:00, scopes: https://database.windows.net//User.Read https://database.windows.net//.default. source: IdentityProvider
23-11-22 10:15:44.3344600 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) Fetched access token from host login.microsoftonline.com. 
23-11-22 10:15:44.3348000 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) 
[LogMetricsFromAuthResult] Cache Refresh Reason: Expired
[LogMetricsFromAuthResult] DurationInCacheInMs: 4
[LogMetricsFromAuthResult] DurationTotalInMs: 1247
[LogMetricsFromAuthResult] DurationInHttpInMs: 1144

23-11-22 10:15:44.3348250 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - df00e745-1a71-4d37-8f53-ecdf68b3fb9f] (azuredatastudio: 0.0.0.0) TokenEndpoint: ****
23-11-22 10:15:44.3439970 pid:90929 tid:18 sqltools Verbose: 0 : eventTID:5870506 <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetCachedToken|Info>CachedToken changed from null to DmW+w3kELGtGn8Wu/zsz3zB8Ykeoh2rZrqm2UUS1uUw=.
23-11-22 10:15:44.3440300 pid:90929 tid:18 sqltools Verbose: 0 : eventTID:5870506 <sc.SqlInternalConnectionTds.GetFedAuthToken> 4, Finished generating federated authentication token.
23-11-22 10:15:44.3440890 pid:90929 tid:18 sqltools Verbose: 0 : eventTID:5870506 <sc.TdsParser.SendFedAuthToken|SEC> Sending federated authentication token
23-11-22 10:15:44.3442250 pid:90929 tid:18 sqltools Verbose: 0 : eventTID:5870506 TdsParserStateObjectManaged.WritePacket | Info | Session Id e9c0eca6-632b-403b-88f2-072a121527ff, SendAsync Result 0
23-11-22 10:15:44.3442580 pid:90929 tid:18 sqltools Verbose: 0 : eventTID:5870506 TdsParserStateObjectManaged.WritePacket | Info | Session Id e9c0eca6-632b-403b-88f2-072a121527ff, SendAsync Result 0
23-11-22 10:15:44.3581780 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Checking client info returned from the server..
23-11-22 10:15:44.3582090 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Saving token response to cache..
23-11-22 10:15:44.3582770 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:44.3582940 pid:90929 tid:17 sqltools Verbose: 0 : Before cache access, acquiring lock for token cache
23-11-22 10:15:44.3587870 pid:90929 tid:17 sqltools Verbose: 0 : Before access, the store has changed
23-11-22 10:15:44.3672070 pid:90929 tid:17 sqltools Verbose: 0 : Read '50208' bytes from storage
23-11-22 10:15:44.3672140 pid:90929 tid:17 sqltools Verbose: 0 : Deserializing the store
23-11-22 10:15:44.3675170 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Clearing user token cache accessor.
23-11-22 10:15:44.3675430 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [SaveTokenResponseAsync] Saving AT in cache and removing overlapping ATs...
23-11-22 10:15:44.3675500 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Looking for scopes for the authority in the cache which intersect with https://database.windows.net//.default
23-11-22 10:15:44.3675550 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting access tokens: 2
23-11-22 10:15:44.3675640 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Intersecting scope entries count - 1
23-11-22 10:15:44.3675720 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Matching entries after filtering by user - 1
23-11-22 10:15:44.3675820 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [SaveTokenResponseAsync] Saving Id Token and Account in cache ...
23-11-22 10:15:44.3675890 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [SaveTokenResponseAsync] Saving RT in cache...
23-11-22 10:15:44.3676230 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) IsLegacyAdalCacheEnabled: yes
23-11-22 10:15:44.3682990 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [AdalCacheOperations] Deserialized 1 items to ADAL token cache. 
23-11-22 10:15:44.3683930 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) [AdalCacheOperations] Serializing token cache with 1 items. 
23-11-22 10:15:44.3684180 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting refresh tokens: 2
23-11-22 10:15:44.3684290 pid:90929 tid:17 sqltools Verbose: 0 : After access
23-11-22 10:15:44.3684320 pid:90929 tid:17 sqltools Verbose: 0 : After access, cache in memory HasChanged
23-11-22 10:15:44.3684400 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting access tokens: 2
23-11-22 10:15:44.3684500 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting refresh tokens: 2
23-11-22 10:15:44.3686120 pid:90929 tid:17 sqltools Verbose: 0 : Serializing '50207' bytes
23-11-22 10:15:44.3691400 pid:90929 tid:17 sqltools Information: 0 : Released local lock
23-11-22 10:15:44.3691630 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) 
	=== Token Acquisition finished successfully:
23-11-22 10:15:44.3691720 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0)  AT expiration time: 2023-11-22 7:21:57PM +00:00, scopes: https://database.windows.net//User.Read https://database.windows.net//.default. source: IdentityProvider
23-11-22 10:15:44.3691780 pid:90929 tid:17 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) Fetched access token from host login.microsoftonline.com. 
23-11-22 10:15:44.3691940 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) 
[LogMetricsFromAuthResult] Cache Refresh Reason: Expired
[LogMetricsFromAuthResult] DurationInCacheInMs: 14
[LogMetricsFromAuthResult] DurationTotalInMs: 1256
[LogMetricsFromAuthResult] DurationInHttpInMs: 1238

23-11-22 10:15:44.3691990 pid:90929 tid:17 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:44Z - a4699e40-2861-4391-96f4-2dc8b90f595c] (azuredatastudio: 0.0.0.0) TokenEndpoint: ****
23-11-22 10:15:44.3692580 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetCachedToken|Info>CachedToken changed from null to zI2/uxAPJmsxbmVKDAtrCpWPnXpc0IU8tx1XUAtC2zI=.
23-11-22 10:15:44.3692650 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc.SqlInternalConnectionTds.GetFedAuthToken> 5, Finished generating federated authentication token.
23-11-22 10:15:44.3692690 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc.TdsParser.SendFedAuthToken|SEC> Sending federated authentication token
23-11-22 10:15:44.3693140 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 TdsParserStateObjectManaged.WritePacket | Info | Session Id 295c1f54-7265-4c6b-abe1-7e821cf9ad5a, SendAsync Result 0
23-11-22 10:15:44.3693350 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 TdsParserStateObjectManaged.WritePacket | Info | Session Id 295c1f54-7265-4c6b-abe1-7e821cf9ad5a, SendAsync Result 0
23-11-22 10:15:44.5547770 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 2, Session Id 295c1f54-7265-4c6b-abe1-7e821cf9ad5a
23-11-22 10:15:44.5548180 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 2, Session Id 295c1f54-7265-4c6b-abe1-7e821cf9ad5a, Packet DataLeft 409
23-11-22 10:15:44.5554210 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc.AppConfigManager.FetchConfigurationSection|INFO>: Unable to load custom `AppContextSwitchOverrides`. Default value of `T` type returns.
23-11-22 10:15:44.5555570 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Entry point.
23-11-22 10:15:44.5555640 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc.SqlAppContextSwitchManager.ApplyContextSwitches|INFO> Exit point.
23-11-22 10:15:44.5562170 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 SqlError.ctor | ERR | Info Number 18456, Error State 1, Error Class 14, Error Message 'Login failed for user '<token-identified principal>'.', Procedure '', Line Number 1
23-11-22 10:15:44.5574200 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|GetCachedToken|Info>Retrieved cached token zI2/uxAPJmsxbmVKDAtrCpWPnXpc0IU8tx1XUAtC2zI=.
23-11-22 10:15:44.5574660 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|CheckCanRetry|Error>Cannot retry when exception is not timeout.
23-11-22 10:15:44.5576360 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 <sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 5
23-11-22 10:15:44.5578150 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 TdsParserStateObjectManaged.Dispose | Info | State Object Id 2, Session Id 295c1f54-7265-4c6b-abe1-7e821cf9ad5a, Disposing session Handle and counters.
23-11-22 10:15:44.5578580 pid:90929 tid:20 sqltools Verbose: 0 : eventTID:5870512 TdsParserStateObjectManaged.Dispose | Info | State Object Id 2, Session Id 295c1f54-7265-4c6b-abe1-7e821cf9ad5a, sessionHandle is available, disposing session.
23-11-22 10:15:44.5606740 pid:90929 tid:17 sqltools Verbose: 0 : eventTID:5870505 SqlConnection.Retry | Info | Object Id 2
Expand for logs (for successful scenario) 
23-11-22 10:15:47.0786520 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) 
=== Request Data ===
Authority Provided? - True
Scopes - https://database.windows.net//.default
Extra Query Params Keys (space separated) - 
ApiId - AcquireTokenSilent
IsConfidentialClient - False
SendX5C - False
LoginHint ? False
IsBrokerConfigured - False
HomeAccountId - False
CorrelationId - 953faa6e-fe65-46c2-a023-7dcab8ee601b
UserAssertion set: False
LongRunningOboCacheKey set: False
Region configured: 

23-11-22 10:15:47.0786630 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) === Token Acquisition (SilentRequest) started:
	 Scopes: https://database.windows.net//.default
	Authority Host: login.windows.net
23-11-22 10:15:47.0786900 pid:90929 tid:15 sqltools Verbose: 0 : Before cache access, acquiring lock for token cache
23-11-22 10:15:47.0791420 pid:90929 tid:15 sqltools Verbose: 0 : Before access, the store has changed
23-11-22 10:15:47.0793450 pid:90929 tid:15 sqltools Verbose: 0 : Read '50208' bytes from storage
23-11-22 10:15:47.0793480 pid:90929 tid:15 sqltools Verbose: 0 : Deserializing the store
23-11-22 10:15:47.0795210 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z] (azuredatastudio: 0.0.0.0) [Internal cache] Clearing user token cache accessor.
23-11-22 10:15:47.0795420 pid:90929 tid:15 sqltools Verbose: 0 : After access
23-11-22 10:15:47.0799950 pid:90929 tid:15 sqltools Information: 0 : Released local lock
23-11-22 10:15:47.0800040 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) [Internal cache] Total number of cache partitions found while getting access tokens: 2
23-11-22 10:15:47.0800160 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) [FindAccessTokenAsync] Discovered 9 access tokens in cache using partition key: 3e7d7b79-6622-4a75-b22f-d5db22b6978c.72f988bf-86f1-41af-91ab-2d7cd011db47
23-11-22 10:15:47.0800360 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:47.0800880 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) Access token is not expired. Returning the found cache entry. [Current time (11/22/2023 18:15:47) - Expiration Time (11/22/2023 19:21:57 +00:00) - Extended Expiration Time (11/22/2023 19:21:57 +00:00)]
23-11-22 10:15:47.0800990 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) Returning access token found in cache. RefreshOn exists ? False
23-11-22 10:15:47.0813790 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) [Region discovery] Not using a regional authority. 
23-11-22 10:15:47.0815950 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) 
	=== Token Acquisition finished successfully:
23-11-22 10:15:47.0816060 pid:90929 tid:15 sqltools Information: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0)  AT expiration time: 2023-11-22 7:21:57PM +00:00, scopes: https://database.windows.net//User.Read https://database.windows.net//.default. source: Cache
23-11-22 10:15:47.0816180 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) 
[LogMetricsFromAuthResult] Cache Refresh Reason: NotApplicable
[LogMetricsFromAuthResult] DurationInCacheInMs: 0
[LogMetricsFromAuthResult] DurationTotalInMs: 2
[LogMetricsFromAuthResult] DurationInHttpInMs: 0

23-11-22 10:15:47.0816210 pid:90929 tid:15 sqltools Critical: 0 : False MSAL 4.56.0.0 MSAL.NetCore .NET 7.0.11 Darwin 23.2.0 Darwin Kernel Version 23.2.0: Thu Nov  9 06:29:42 PST 2023; root:xnu-10002.60.71.505.1~3/RELEASE_ARM64_T6020 [2023-11-22 18:15:47Z - 953faa6e-fe65-46c2-a023-7dcab8ee601b] (azuredatastudio: 0.0.0.0) TokenEndpoint: ****
23-11-22 10:15:47.0817140 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetCachedToken|Info>CachedToken changed from null to zI2/uxAPJmsxbmVKDAtrCpWPnXpc0IU8tx1XUAtC2zI=.
23-11-22 10:15:47.0817290 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 <sc.SqlInternalConnectionTds.GetFedAuthToken> 8, Finished generating federated authentication token.
23-11-22 10:15:47.0817340 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 <sc.TdsParser.SendFedAuthToken|SEC> Sending federated authentication token
23-11-22 10:15:47.0818430 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 TdsParserStateObjectManaged.WritePacket | Info | Session Id 01fef83f-d86a-4b83-bf3c-65b651ff7055, SendAsync Result 0
23-11-22 10:15:47.0818780 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 TdsParserStateObjectManaged.WritePacket | Info | Session Id 01fef83f-d86a-4b83-bf3c-65b651ff7055, SendAsync Result 0
23-11-22 10:15:47.1722000 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 TdsParserStateObjectManaged.ReadSyncOverAsync | Info | State Object Id 3, Session Id 01fef83f-d86a-4b83-bf3c-65b651ff7055
23-11-22 10:15:47.1724180 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 TdsParserStateObjectManaged.ReleasePacket | Info | State Object Id 3, Session Id 01fef83f-d86a-4b83-bf3c-65b651ff7055, Packet DataLeft 746
23-11-22 10:15:47.1726460 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 <sc.TdsParser.TryRun|SEC> Received login acknowledgement token
23-11-22 10:15:47.1734900 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 <sc|ActiveDirectoryAuthenticationTimeoutRetryHelper|SetState|Info>State changed from NotStarted to HasLoggedIn.
23-11-22 10:15:47.1735590 pid:90929 tid:11 sqltools Verbose: 0 : eventTID:5870059 <prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1, Pooled database connection created.
23-11-22 10:15:47.1738460 pid:90929 tid:22 sqltools Verbose: 0 : eventTID:5870567 TdsParser.Connect | SEC | Connection Object Id 9, Authentication Mode: ActiveDirectoryInteractive

Microsoft.Data.SqlClient version: 5.1.1
.NET 7

Similar issue: #970
@DavoudEshtehari DavoudEshtehari added the 🆕 Triage Needed For new issues, not triaged yet. label Nov 22, 2023
@DavoudEshtehari
Copy link
Contributor

We'll discuss it on the next bug triage ;)

@kf-gonzalez kf-gonzalez removed the 🆕 Triage Needed For new issues, not triaged yet. label Nov 28, 2023
@DavoudEshtehari DavoudEshtehari linked a pull request Dec 18, 2023 that will close this issue
Fix | Fix driver to not send expired token and refresh token first before sending it. #2273
Merged
@arellegue arellegue mentioned this issue Jan 18, 2024
Merged
@OskarKlintrot
Copy link

We have been seeing this exception a lot in our environments. However, I wonder if this will fix one of our cases. Sometimes we get this exception when we swap a staging slot out in production on our Azure App Services. My guess (I think someone verified this somewhere, but I can't find that issue/comment atm) is that the staging slot, after swapped and now being the prod slot) still uses the staging slot identity when retrieving an access token. Did #2273 only fix the issue that the token is not always refreshed after being expired or might my issue have been resolved as well?

@tompazourek
Copy link

tompazourek commented May 6, 2024 •
edited
Loading

I see this issue has been fixed in the 5.2.0 release, but I'm still seeing these errors even after updating.

The errors always happen when the application is running longer than 24 hours, and the error messages match, so I expect it's the same token renew issue.

Can this be re-opened?

@David-Engel
Copy link
Contributor

@tompazourek This issue was for an intermittent issue. Since yours is consistent after 24 hours, it's likely different. File a new issue with all details (particularly exception stack, connection string authentication options, and, if you aren't using built-in authentication, details of how you are obtaining / managing access tokens).

@David-Engel David-Engel mentioned this issue Jun 11, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
SqlClient Triage Board
Status: Closed
Milestone
No milestone
6 participants
@tompazourek @OskarKlintrot @cheenamalhotra @David-Engel @DavoudEshtehari @kf-gonzalez