MSAL AcquiretokenSilent success case taking 1+ second

[MarkZuber]

Which Version of MSAL are you using ?
MSAL 3.0.1-preview

Platform
net45, netcore

The code below is consistently causing 1-1.2 seconds of time for acquire token silent. It is expected that this should take 5-10ms.

for (int i = 0; i < 5000; i++)
{
  Console.Write($"Attempt {i}: ");
  var start = DateTime.Now;
  var result2 = await app.AcquireTokenSilentAsync(scopes, account).ConfigureAwait(false);
  var length = DateTime.Now - start;
  Console.WriteLine($"{length.TotalMilliseconds}ms");
}

[MarkZuber]

This is a bug in the test, but we should see if there's a way for us to detect it. The stress test was sending in https://management.core.windows.net//.default (note the double slash before default) so the cache lookup filtering by scopes was failing. and then we were doing a full AT token exchange which is where the time came from. The server ends up taking the // in the scope and normalizing it and when we cache the token, we cache it with /.default as expected (which is where the later lookup mismatch occurs). So perhaps we should see if we can parse the scopes and if they start with https ensure they're a proper url?

[jmprieur]

This will be fixed on the service side (ETA beginning of May normally)

[jmprieur]

@MarkZuber : any objection to closing it?

[MarkZuber]

I'd like to keep this active for tracking until we verify the server has fixed this issue.

[jmprieur]

then I get I'll move it to 3.0.5+

[stevehurcombe]

@MarkZuber do you have any idea when this will get fixed? This is blocking us.

[jmprieur]

@MarkZuber : apprently the change should be in prod now.
do you still see the issue?

[stevehurcombe]

@jmprieur My path is a bit different.
I've been lurking here waiting for the right time to upgrade to version 3.x. I saw this issue and I'm following it as I'm seeing the same issue in 2.7.1. A "long" delay accessing the token on every startup.

@MarkZuber implied that this was a server side issue so I did expect 2.7.1 to benefit as well.

Do we also need to upgrade to version 3.0.8?

Cheers
Steve

[stevehurcombe]

@jmprieur I've upgraded to 3.08 and Xamarin Forms 4 Pre-10 and AcquireTokenSilentAsync is still taking ~2-3 seconds on startup. This is on a Samsung S7 Edge.

The LogCat output is:

05-17 21:04:16.928: D/Mono(12164): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:17 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] MSAL MSAL.Xamarin.Android with assembly version '3.0.8.0', file version '3.0.8.0' and informational version '3.0.8+5db620ee347d54948b2775699985ae7a4d2bef1a'. TelemetryCorrelationId(c7d13280-4665-4a1a-aa46-b5f9f648cc53)
05-17 21:04:16.928: D/Mono(12164): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:17 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] === OnBehalfOfParameters ===
05-17 21:04:16.928: D/Mono(12164): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:17 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] 
05-17 21:04:16.928: D/Mono(12164): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:17 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] === Token Acquisition (SilentRequest) started:
05-17 21:04:18.142: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Looking up access token in the cache.
05-17 21:04:18.157: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Filtering by home account id item count before 1 after 1
05-17 21:04:18.157: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Tenant id: xxxxxxx.onmicrosoft.com
05-17 21:04:18.157: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Filtering by tenant id item count before 1 after 1
05-17 21:04:18.157: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Matching entry count -1
05-17 21:04:18.166: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Matching entry count after filtering by scopes - 1
05-17 21:04:18.183: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] Access token is not expired. Returning the found cache entry. [Current time (05/17/2019 20:04:18) - Expiration Time (05/17/2019 20:50:31 +00:00) - Extended Expiration Time (01/01/0001 00:00:00 +00:00)]
05-17 21:04:18.206: W/android.os.Debug(4900): (False) MSAL 3.0.8.0 MSAL.Xamarin.Android 26 [05/17/2019 20:04:18 - c7d13280-4665-4a1a-aa46-b5f9f648cc53] === Token Acquisition finished successfully. An access token was returned with Expiration Time: 05/17/2019 20:50:31 +00:00 ===

[jmprieur]

@stevehurcombe the startup delay a different issue: this is instance discovery. you might want to follow #1174 for that one.

Closing this one as it's fixed.