[BUG] Slow VisualStudioCredential performance when accessing Azure App Config in a multi-tenant setup

[jsquire]

Issue Transfer

This issue has been transferred from the Azure SDK for .NET repository, #41433.

AppConfig Team: This appears to be related to the AppConfig extension and not the credential itself, as other uses of the same credential - such as KeyVault access - do not have suffer the same slow performance. If information on the Azure.Identity credentials is needed, please reach out internally for discussion.

Please be aware that @clbarrett is the author of the original issue and include them for any questions or replies.

Details

Library name and version

Microsoft.Azure.AppConfiguration.AspNetCore 7.0.0
Azure.Identity 1.10.4

Describe the bug

The situation is that I'm setting up a ChainedTokenCredential to use the Visual Studio Credentials followed by Azure CLI Credentials when running locally. Weirdly I'm seeing a connection time between 15-45 seconds when calling builder.Configuration.AddAzureAppConfiguration(...) using the Visual Studio Credential. But the connection is less than a second when using Azure CLI alone. Same behavior persists when I used only Visual Studio Credentials. Neither do I have the same issue connecting to an Azure Key Vault. Do note that this is in a multi-tenant scenario.

Expected behavior

Expect that the call to builder.Configuration.AddAzureAppConfiguration(...) completes in less than a second, just like when adding a Key Vault or using the Azure CLI Credentials.

Actual behavior

The builder.Configuration.AddAzureAppConfiguration(...) call takes anywhere from 15 to 45 seconds to complete.

Reproduction Steps

My user is on Tenant A while my App Config is on Tenant B. The Tenant ID in my code is the Tenant B TenantID.

List<TokenCredential> credentials = new List<TokenCredential>();
VisualStudioCredentialOptions vscOptions = new VisualStudioCredentialOptions()
{
	AdditionallyAllowedTenants = { "*" },
	//Not a real Tenant ID
	TenantId = "88909005-48a7-48b4-b99b-73b1295c6424",
};
credentials.Add(new VisualStudioCredential(vscOptions));
var AzureIdentity = new ChainedTokenCredential(credentials.ToArray());

config.AddAzureAppConfiguration(options =>
{
    options.Connect("https://insertappconfignamehere.azconfig.io/", AzureIdentity)
            .Select(KeyFilter.Any, LabelFilter.Null);
});

For comparison swap VisualStudioCredential & Options with AzureCliCredential & Options.

Environment

Windows 11
Visual Studio 2022 64 bit - Version 17.8.3
C#
Asp.Net 6.0

[clbarrett]

Hi, I'm available to answer any questions. Would like to use this in our development team as it is easier than having all of our developers install the Azure CLI where this would be the only thing they use it for.

[clbarrett]

Just noticed this over in Azure Portal. This is a dedicated App Config for testing purposes so I'm the only one using it.

This is a 1 hour time frame. The 11.5 ms connection is from the Azure CLI Azure Identity access.

This is the 6 hour time frame that I've been doing my development & testing of the Azure Identity Credentials in C#.
You can't even see the Azure CLI accesses due to how skewed the scale is here. The tallest peak is over 30 seconds. This is also an average. I have been running several tests back to back. So the averages are lower than the maximum I've seen.

[amerjusupovic]

Hi @clbarrett, first could you tell me what region you were connecting to and if this is still an issue? We were made aware of long request times across the App Configuration service a couple days ago, but there should have been a fix going out yesterday.

[clbarrett]

Yes, I am still seeing the issue. My App Config is in the East US group. I can try creating one in a different region if that would help you.
Ran it twice this morning.
First time 18.3 seconds
Second time 11.25 seconds

[amerjusupovic]

Do you think you could send any client request IDs that you have? Also, you haven't had any requests timeout or fail, just long request times?

[clbarrett]

Where would I find the client request IDs to provide?

I had one timeout but I'm pretty sure it was a network issue on my side. Out of several dozens of attempts I have only had the one.

[amerjusupovic]

from Logging with the Azure SDK for .NET

using AzureEventSourceListener listener =
         AzureEventSourceListener.CreateConsoleLogger(System.Diagnostics.Tracing.EventLevel.Informational);

Adding this line just before you call Build() on your configuration builder will output the requests made to App Configuration to the console. In your console, you should see a line called x-ms-client-request-id under an Azure-Core request that starts like this:

[Informational] Azure-Core: Request [] GET

[clbarrett]

Excellent. Will test with this sometime this weekend.

[clbarrett]

`[17:16:24 INF] Configuration Setup: Loading Source [Azure App Config: redacted with labels [redacted, App Config URI: https://redacted.azconfig.io/]
[Informational] Azure-Identity: VisualStudioCredential.GetToken invoked. Scopes: [ https://redacted.azconfig.io/.default ] ParentRequestId: 6b3a9881-efa8-4c46-91c5-b9c93cc79d81
[Informational] Azure-Identity: VisualStudioCredential.GetToken succeeded. Scopes: [ https://redacted.azconfig.io/.default ] ParentRequestId: 6b3a9881-efa8-4c46-91c5-b9c93cc79d81 ExpiresOn: 2024-01-27T01:22:00.5114908+00:00
[Informational] Azure-Core: Request [6b3a9881-efa8-4c46-91c5-b9c93cc79d81] GET https://redacted.azconfig.io/kv?key=REDACTED&label=REDACTED&api-version=2023-10-01
Accept:application/vnd.microsoft.appconfig.kvset+json, application/problem+json
Correlation-Context:REDACTED
User-Agent:Microsoft.Extensions.Configuration.AzureAppConfiguration/7.0.0,azsdk-net-Data.AppConfiguration/1.3.0 (.NET 6.0.26; Microsoft Windows 10.0.22621)
x-ms-client-request-id:6b3a9881-efa8-4c46-91c5-b9c93cc79d81
x-ms-return-client-request-id:true
Authorization:REDACTED
client assembly: Azure.Data.AppConfiguration
[Informational] Azure-Core: Response [6b3a9881-efa8-4c46-91c5-b9c93cc79d81] 200 OK (00.5s)
Date:Sat, 27 Jan 2024 00:16:34 GMT
Transfer-Encoding:chunked
Connection:keep-alive
ETag:"7VLJDac8p7GKD2ESFPQ8D_35ziIYkpvY9nX61MiW60Y"
Sync-Token:zAJw6V16=NToxOSM1ODUzMzc4OQ==;sn=58533789
x-ms-request-id:1d7027d8-9f08-4b7d-a0ec-ecfa2213820d
x-ms-client-request-id:6b3a9881-efa8-4c46-91c5-b9c93cc79d81
x-ms-correlation-request-id:1d7027d8-9f08-4b7d-a0ec-ecfa2213820d
Strict-Transport-Security:max-age=31536000; includeSubDomains
Access-Control-Allow-Origin:*
Content-Type:application/vnd.microsoft.appconfig.kvset+json; charset=utf-8

[Informational] Azure-Core: Request [08a32d23-f39a-4268-bfc3-d761d3eaba5a] GET https://redacted.azconfig.io/kv?key=REDACTED&label=REDACTED&api-version=2023-10-01
Accept:application/vnd.microsoft.appconfig.kvset+json, application/problem+json
Correlation-Context:REDACTED
User-Agent:Microsoft.Extensions.Configuration.AzureAppConfiguration/7.0.0,azsdk-net-Data.AppConfiguration/1.3.0 (.NET 6.0.26; Microsoft Windows 10.0.22621)
x-ms-client-request-id:08a32d23-f39a-4268-bfc3-d761d3eaba5a
x-ms-return-client-request-id:true
Authorization:REDACTED
Sync-Token:zAJw6V16=NToxOSM1ODUzMzc4OQ==
client assembly: Azure.Data.AppConfiguration
[Informational] Azure-Core: Response [08a32d23-f39a-4268-bfc3-d761d3eaba5a] 200 OK (00.1s)
Date:Sat, 27 Jan 2024 00:16:35 GMT
Transfer-Encoding:chunked
Connection:keep-alive
ETag:"k9BKssO55_h7gMtsNmyC8VAYaxe3ag_hnh8M5K4RLB4"
Sync-Token:zAJw6V16=NToxOSM1ODUzMzc4OQ==;sn=58533789
x-ms-request-id:0f977a39-70f5-4dd8-a146-60fe8f9dd94e
x-ms-client-request-id:08a32d23-f39a-4268-bfc3-d761d3eaba5a
x-ms-correlation-request-id:0f977a39-70f5-4dd8-a146-60fe8f9dd94e
Strict-Transport-Security:max-age=31536000; includeSubDomains
Access-Control-Allow-Origin:*
Content-Type:application/vnd.microsoft.appconfig.kvset+json; charset=utf-8

[Informational] Azure-Core: Request [311a948e-473b-4857-81e2-ea2d78a586ff] GET https://redacted.azconfig.io/kv?key=REDACTED&label=REDACTED&api-version=2023-10-01
Accept:application/vnd.microsoft.appconfig.kvset+json, application/problem+json
Correlation-Context:REDACTED
User-Agent:Microsoft.Extensions.Configuration.AzureAppConfiguration/7.0.0,azsdk-net-Data.AppConfiguration/1.3.0 (.NET 6.0.26; Microsoft Windows 10.0.22621)
x-ms-client-request-id:311a948e-473b-4857-81e2-ea2d78a586ff
x-ms-return-client-request-id:true
Authorization:REDACTED
Sync-Token:zAJw6V16=NToxOSM1ODUzMzc4OQ==
client assembly: Azure.Data.AppConfiguration
[Informational] Azure-Core: Response [311a948e-473b-4857-81e2-ea2d78a586ff] 200 OK (00.1s)
Date:Sat, 27 Jan 2024 00:16:35 GMT
Transfer-Encoding:chunked
Connection:keep-alive
ETag:"00wWELzclWef22f82qcUDI7FbJweVOoKWZDA_JoUeD0"
Sync-Token:zAJw6V16=NToxOSM1ODUzMzc4OQ==;sn=58533789
x-ms-request-id:e8dcf893-efb3-4a71-b8a9-3ed42f8e0bf0
x-ms-client-request-id:311a948e-473b-4857-81e2-ea2d78a586ff
x-ms-correlation-request-id:e8dcf893-efb3-4a71-b8a9-3ed42f8e0bf0
Strict-Transport-Security:max-age=31536000; includeSubDomains
Access-Control-Allow-Origin:*
Content-Type:application/vnd.microsoft.appconfig.kvset+json; charset=utf-8

[17:16:35 INF] Configuration Setup: Source [Azure App Config: redacted] with labels [redacted] Successfully Loaded
[17:16:35 INF] Config - App Config Loaded in 00:10.92`

Found a spare minute to run this and here is the output. Let me know if you need the app config name. While it doesn't hold anything sensitive I prefer not putting info out on the internet. I also included the before & after messages along with the stopwatch results for this run.

For comparison, here is the timing results for the Azure CLI Credential:
[17:26:02 INF] Configuration Setup: Source [Azure App Config: Redacted] with labels [Redacted] Successfully Loaded
[17:26:02 INF] Config - App Config Loaded in 00:01.72

[clbarrett]

Any update on this? I'm at the point of just abandoning the Visual Studio Credentials altogether due to the massive performance hit.

[amerjusupovic]

Sorry for the delay, unfortunately I wasn't able to find anything based on your logs and I'm not aware of any other issues with the App Configuration service specifically that would still be causing this. When I tried to reproduce this, I did see that the request to get a credential took a long time, but we didn't see any long response times from App Configuration. If you'd like to send more recent logs I can try to look again.

[Macro21]

Same here... In local with appsettings.json my webapi starts in 5 seconds. With App Configuration 32

[amerjusupovic]

Did you also see long request durations in the portal for your App Configuration store? If you could send client request ids as mentioned above, I could try and look into this again. I'm not able to replicate this locally with the newest provider versions, so it's hard for me to pinpoint where this is coming from.

[Macro21]

I haven't been able to put the configuration you recommended, but I found out this:

When you create the App Configuration in Azure, in the "networking" tab the "automatic" option is set. By changing that option to "enabled" with public access, it has gone from taking 32 seconds to 9.