Duende Software
Slow /.well-known/openid-configuration endpoints #17
-
|
Which version of Duende IdentityServer are you using? have a 99th percentile performance of ~1 sec with peaks up to 20 secs during ~ 5.45 AM GMT+1 App Insights Performance Trace During peaks to ~20 secs, other endpoints slow down considerably as well
To Reproduce Expected behavior Log output/exception with stacktrace Additional context We found DuendeArchive/Support#1361 but no improvement occurred after updating Azure.Core to 1.44. NuGet Versions with ~20ms 99th percentile (Pre 8th January) NuGet Versions with ~1sec 99th percentile (Post 8th January) We have added aggressive caching with a custom
During the time between 14:30 - 14:40, I ran a dummy app to poll the discovery endpoint in an interval - latency was perfectly fine there. After stopping the dummy app, the regular traffic calling the endpoint started seeing latencies of ~1 sec again. The relevant caching code for var key = $"{_memoryKeyPrefix}{baseUrl}-{issuerUri}";
if (_memoryCache.TryGetValue(key, out Dictionary<string, object>? discoveryDocument) && discoveryDocument != null)
return discoveryDocument;
discoveryDocument = await base.CreateDiscoveryDocumentAsync(baseUrl, issuerUri);
var expiration = _timeProvider.GetUtcNow().AddSeconds(Options.Discovery.ResponseCacheInterval ?? _defaultExpirationInSeconds);
_memoryCache.Set(key, discoveryDocument, expiration);
return discoveryDocument; |
Beta Was this translation helpful? Give feedback.
Replies: 13 comments 36 replies
-
|
It indeed looks like something happened in that upgrade, yes. Looking at the example trace for the GET request indicates that the problem is outside of the IdentityServer pipeline. The *) To be 100% correct, there are a few infrastructure level things that are done outside of that block. The first is that the activity only fires if the path matches an IdentityServer endpoint => the endpoint resolution happens outside of the block. It's a simple for loop with only in memory dependencies and I cannot imagine how that would take close to a second. Also if you are using the dynamic providers feature, handling of those is outside of the My overall feeling here based on the diagnostics shared is that it's something happening before or after the actual IdentityServer code is invoked. Did you do any code changes as part of the upgrade? Any changes to infrastructure? |
Beta Was this translation helpful? Give feedback.
-
|
Thanks for your response. There is no pre / post processing there but I'll try to get more diagnostics from the NET Core pipeline. The strange thing is, that its only affecting one region in Azure - North Europe has about 20% traffic of West Europe but no issues at all. I'll try to reproduce locally as we see the problem in 3 different environments. I'll also further investigate transitive dependencies Also note, all other protocol endpoints (/introspect, /token etc.) behave normal. Its just the well-known one. |
Beta Was this translation helpful? Give feedback.
-
|
Checking App Insights today, we've seen the following:
/well-known Endpoints have very high latency while other Duende Protocol Endpoints (Introspect, Token) increase as well, just not as much. I'll investige further within the ASP.NET Core pipeline but if you could check on your end as well @AndersAbel to see if there is a difference between the endpoints. We're using YARP as proxy in front of identity server, I'll check if there is a problem there. |
Beta Was this translation helpful? Give feedback.
-
|
Thanks for sharing those stats. The ./well-known endpoints are actually the ones I consider most simple in their implementation. There is less code to run and less storage/database access. The token endpoint in comparison is more complex, but also (as far as I remember) utilizes all storage/config that the ./well-known endpoints to. I do not doubt that this is a problem, but to properly troubleshoot we would need full activity traces that shows timing all the way from the client's requests to how it is handled on the server side. The only tangible data point we have so far is the one I referenced above and that one shows that the execution of the discovery endpoint class only takes up a fraction of the total time. Are you using the dynamic providers feature? |
Beta Was this translation helpful? Give feedback.
-
|
I've opened another issue for YARP and after collecting metrics and checking with the team there, it seems that YARP does not cause the latency. Metrics suggest that the request is immediatly forwarded to the network stack. We do not use dynamic providers. As I've mentioned above, we started service the
In comparison, the I'll enable ASP.NET core telemetry to see where the additional time comes from. |
Beta Was this translation helpful? Give feedback.
-
I think that is the right next step. Right now we don't know where the time is spent and for any performance issue metrics is the only way to solve it. There are things in the discovery endpoint as well as in the IdentityServer endpoint selection/routing that could potentially cause timing issues (never say never in these cases until it is proved). The only thing I can say is that the numbers shared so far indicate that the issue is outside of the IdentityServer middleware. That doesn't mean IdentityServer is not to blame - we won't know until we have metrics that show where the issue is. |
Beta Was this translation helpful? Give feedback.
-
|
I'll set metrics logging up, that will require some code changes to use the new OpenTelemetry packages. We noticed that those long running requests come in pairs within a range of 10 ms from the same client /.well-known/openid-configuration one of them finishes within the expected latency, the other is at 1 sec, as if there is a lock / resource contest. |
Beta Was this translation helpful? Give feedback.
-
|
(note: we're moving this issue to our new community discussions) |
Beta Was this translation helpful? Give feedback.
-
|
We suspect that this might be a problem with the Azure Networking infrastructure as the root endpoint '/' also adds random 1 sec latencies. We'll keep you updated once we involved Azure Support. |
Beta Was this translation helpful? Give feedback.
-
|
@4865783a5d do you have any feedback on this that could help shed a light on the root cause? We are working with @mathitharmalingam-aqi that has a similar issue reported below that we try to solve. |
Beta Was this translation helpful? Give feedback.
-
|
@AndersAbel Not yet, we're still gathering data and network traces to rule certain things in or out. |
Beta Was this translation helpful? Give feedback.
-
|
Any solution to this? I added a custom middleware to log the request to well-known endpoint, just before handing the request to the identity server. 
As you can see, almost all the time is spent in the identity server middleware. Our app is running in Azure ServiceFabric V10.1.2493.9590. I updated the Azure.Core to 1.45 and tried the preview identity server package V7.2.0-preview.1. |
Beta Was this translation helpful? Give feedback.
-
|
Which version of .NET 8 are you on, and which version of Microsoft.Data.SqlClient? |
Beta Was this translation helpful? Give feedback.
-
|
@4865783a5d I believe your company has priority support - if the problem still persists would you mind reaching out to our priority email alias? |
Beta Was this translation helpful? Give feedback.
-
|
@maartenba Yes indeed, we just deployed a change in our infrastructure to not have a proxy between our global load balancer and identity server, as we strongly assumed (based on telemetry data on YARP + Identity Server) that the well-known problem was caused by a network issue in Azure. I'll be able to post feedback here tomorrow, and in case it is resolved will reach out over our priority support. |
Beta Was this translation helpful? Give feedback.
-
|
We still expirience massive latency issues, comparing with /connect/token which does a whole lot of more work:
vs. We cached both /.well-known endpoints, they're not touching any other PaaS service like Key Vault or DB which would give a reason for such an increase.
|
Beta Was this translation helpful? Give feedback.
-
|
@4865783a5d let's connect via priority support if possible? |
Beta Was this translation helpful? Give feedback.
-
|
IdentityServer 7.2 was just released with a preview feature that can cache the output of the discovery endpoint. Can you please try that and see if it makes a difference? |
Beta Was this translation helpful? Give feedback.
-
|
@maartenba |
Beta Was this translation helpful? Give feedback.
-
|
@mathitharmalingam-aqi Are you using any non-Duende extensions to IdentityServer? E.g. RSK? |
Beta Was this translation helpful? Give feedback.
-
|
@maartenba - no we don't use any non-Duende extension to IdentityServer. Here is the list of packages used in deployed version. |
Beta Was this translation helpful? Give feedback.
-
|
Can you try pinning Microsoft.Data.SqlClient in this list? |
Beta Was this translation helpful? Give feedback.
-
|
@maartenba - the latest Duende packages did not solve the issue. |
Beta Was this translation helpful? Give feedback.
-
|
@AndersAbel @maartenba After enabling more log categories, I was able to pin point this ~1 sec latency increase:
It comes from the AspNet Core CORS Middleware. "Cache hit for https://xxx.ch" , origins from Category: Duende.IdentityServer.Services.DefaultCache I'll have a look at that code and see what it does. Update: We deployed a fix (Re-ordering Asp.Net CORS middleware in request pipeline and providing a AllowAll = true service for That fixed the issue: The 99P is not yet recovered but latency has pretty much flatlined. As we didn't deploy anything CORS related since february 2024, it wasn't obvious. We enabled a preflight cache to speed up the That might have had a negative impact we didn't start seeing until late 2024. It is also documented as footnote:
|
Beta Was this translation helpful? Give feedback.
-
|
That's a good find! So it was the ordering of UseIdentityServer() and UseCors() that was causing this for you? |
Beta Was this translation helpful? Give feedback.
-
|
Yes indeed, we did not question the startup routine as it hasn't been changed for quite some time and the performance hit came with a unrelated deployment. Thanks for your combined help! |
Beta Was this translation helpful? Give feedback.
-
|
Just for my understanding, what is the underlying |
Beta Was this translation helpful? Give feedback.
-
|
We're using the |
Beta Was this translation helpful? Give feedback.
-
|
This is good news, that you found something that reduced the execution time substantially. I would however advice to reconsider the generous CORS policy in production. It is a good step in troubleshooting, but there are security implications of having an allow-all CORS policy. |
Beta Was this translation helpful? Give feedback.
-
|
@mathitharmalingam-aqi looks like this may also be something to look into on your end: https://github.com/orgs/DuendeSoftware/discussions/17#discussioncomment-12750421 |
Beta Was this translation helpful? Give feedback.
-
|
@mathitharmalingam-aqi Thanks for sharing those details. What I find interesting is that the slow times are for xhr requests. Would you be able to jump on a call to show me your environment? Please reach out through our contact form and mention that you need to get in touch with me regarding a support issue. |
Beta Was this translation helpful? Give feedback.
-
|
I submitted a contact form. |
Beta Was this translation helpful? Give feedback.
-
|
hello @mathitharmalingam-aqi ! any update about this issue? thanks |
Beta Was this translation helpful? Give feedback.
-
|
👋 Hey folks, I'm currently looking at the code and wondering if you happen to be logging information to the TL;DR: Console Logging in production is slow and can cause performance degradation or issues. Under heavy load, attempts to write to the console output can pile up and consume resources and threads, which can reduce your application's performance. |
Beta Was this translation helpful? Give feedback.
-
I had a call with Anders, now I'm waiting to hear back from Duende. |
Beta Was this translation helpful? Give feedback.
-
|
@martinescalantehughes I see you commented above, do you have a similar issue? As we are still working on investigating this it would be great if you could share some information about your setup and what issues you see. |
Beta Was this translation helpful? Give feedback.
@AndersAbel @maartenba After enabling more log categories, I was able to pin point this ~1 sec latency increase:
It comes from the AspNet Core CORS Middleware.
"Cache hit for https://xxx.ch" , origins from Category: Duende.IdentityServer.Services.DefaultCache
"No CORS policy found for the specified request.", origins from Categroy: Microsoft.AspNetCore.Cors.Infrastructure.CorsMiddleware
I'll have a look at that code and see what it does.
Update: We deployed a fix (Re-ordering Asp.Net CORS middleware in request pipeline and providing a AllowAll = true service for
DefaultCorsPolicyServiceThat fixed the issue:
The 99P is not yet recovered but latency has pretty much flatlined. As we didn'…