6.3.10 timeout issues

[philipwindsora55]

Which version of Duende IdentityServer are you using?
6.3.10

Which version of .NET are you using?
6.0

Describe the bug
We patched IdentityServer as per the CVE. We've gone from 6.3.5 to 6.3.10.

I'm not saying for sure that this patch has started causing issues but they only started happening since I applied the patch so I'm reaching out to see if anyone else has experienced issues.

Our UI is working fine, we can login and edit details however, the following endpoints are timing out:

/.well-known/openid-configuration
/.well-known/openid-configuration/jwks

The timeouts have occurred across our dev and test instances the past few days. I've just rebooted out test instance and .well-known/openid-configuration is loading again.

There are no logs showing in Application Insights, I'm also in the process of raising a ticket with azure support.

[philipwindsora55]

I've turned on trace logging for our test instance and will post the logs once we have them. This might give more insight into why these endpoints are timing out

[sanket-mistry-jm]

We are running to same situation on all of our environments. We had this issue when we used pre-release version as well as public released version. Rebooting seems to resolve the issue, but issue seems to come back after few days and seems consistent.

What is worth noting is that we rollbacked version to 6.3.8 and issue was gone.

What I have noticed is that issue starts occurring mostly during UTC mid-night on lower environment as well as production as far as I can tell. I hope this might help investigate.

[josephdecock]

Thanks for this report. We're investigating. My initial suspicion is that this is related to 6.3.9's update of our dependencies on ASP.NET framework packages. In that version, we updated framework packages from version 6.0.0 to version 6.0.26. This updates our transitive dependency on the System.IdentityModel.Tokens.Jwt and Microsoft.IdentityModel.JsonWebTokens packages past versions that have a known Denial of Service vulnerability.

@sanket-mistry-jm it would be extremely helpful if you could try to reproduce the issue in your environment with the 6.3.9 build of IdentityServer.

In the meantime, since this is preventing application of the hotfix, my recommendation is to apply the workarounds that we describe in the advisory - basically your UI code should not rely on the interaction service to determine if urls are local. You should use the IsLocalUrl api from ASP.NET instead.

[philipwindsora55]

Hi @josephdecock, thanks for looking into this. Is it likely that the same issue effects 7.X.X versions? We are planning to upgrade to dotnet8 and v7 in the very near future.

[sanket-mistry-jm]

@josephdecock, I will see what I can do and report back here.

[sanket-mistry-jm]

FYI, we ran into the same issue again on Production. Again, issue started at almost UTC 12:00 today.

[philipwindsora55]

Our test instance started timing out again today, here are the logs....

Logs from a request that times out

13/08/2024, 09:39:50.064 - Request starting HTTP/1.1 GET https://[redacted]/.well-known/openid-configuration - -
13/08/2024, 09:39:50.065 - All hosts are allowed.
13/08/2024, 09:39:50.065 - Adding HSTS header to response.
13/08/2024, 09:39:50.065 - The request path /.well-known/openid-configuration does not match a supported file type
13/08/2024, 09:39:50.065 - No candidates found for the request path '/.well-known/openid-configuration'
13/08/2024, 09:39:50.065 - Request did not match any endpoints
13/08/2024, 09:39:50.065 - AuthenticationScheme: idsrv was not authenticated.
13/08/2024, 09:39:50.066 - AuthenticationScheme: idsrv was not authenticated.
13/08/2024, 09:39:50.066 - Request path /.well-known/openid-configuration matched to endpoint type Discovery
13/08/2024, 09:39:50.066 - Endpoint enabled: Discovery, successfully created handler: Duende.IdentityServer.Endpoints.DiscoveryEndpoint
13/08/2024, 09:39:50.066 - Invoking IdentityServer endpoint: Duende.IdentityServer.Endpoints.DiscoveryEndpoint for /.well-known/openid-configuration
13/08/2024, 09:39:50.066 - Processing discovery request.
13/08/2024, 09:39:50.066 - Start discovery request
13/08/2024, 09:39:50.066 - Calling into discovery response generator: Duende.IdentityServer.ResponseHandling.DiscoveryResponseGenerator
13/08/2024, 09:39:50.066 - Getting all the keys.
13/08/2024, 09:39:50.066 - Cache miss when loading all keys.
13/08/2024, 09:39:50.066 - Loading keys from store.
13/08/2024, 09:39:50.067 - Entity Framework Core 6.0.5 initialized 'PersistedGrantDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:6.0.5' with options: None
13/08/2024, 09:39:50.067 - Creating DbCommand for 'ExecuteReader'.
13/08/2024, 09:39:50.067 - Created DbCommand for 'ExecuteReader' (0ms).
13/08/2024, 09:39:50.067 - Opening connection to database '[redacted]' on server '[redacted]'.
13/08/2024, 09:39:50.067 - Opened connection to database '[redacted]' on server '[redacted]'.
"13/08/2024, 09:39:50.067 - Executing DbCommand [Parameters=[], CommandType='""Text""', CommandTimeout='30']
SELECT [k].[Id], [k].[Algorithm], [k].[Created], [k].[Data], [k].[DataProtected], [k].[IsX509Certificate], [k].[Use], [k].[Version]
FROM [Keys] AS [k]
WHERE [k].[Use] = N'signing'"
"13/08/2024, 09:39:50.069 - Executed DbCommand (1ms) [Parameters=[], CommandType='""Text""', CommandTimeout='30']
SELECT [k].[Id], [k].[Algorithm], [k].[Created], [k].[Data], [k].[DataProtected], [k].[IsX509Certificate], [k].[Use], [k].[Version]
FROM [Keys] AS [k]
WHERE [k].[Use] = N'signing'"
13/08/2024, 09:39:50.069 - A data reader was disposed.
13/08/2024, 09:39:50.069 - Closing connection to database '[redacted]' on server '[redacted]'.
13/08/2024, 09:39:50.069 - Closed connection to database '[redacted]' on server '[redacted]'.
13/08/2024, 09:39:50.069 - Performing unprotect operation to key {528a74a2-4935-449f-bf9b-99c525077820} with purposes ('C:\home\site\wwwroot', 'DataProtectionKeyProtector').
13/08/2024, 09:39:50.069 - Performing unprotect operation to key {9ff190bf-9bb3-4ec1-9314-95bb4692d19c} with purposes ('C:\home\site\wwwroot', 'DataProtectionKeyProtector').

Logs from a successful request for comparison.

12/08/2024, 09:40:26.426 -  Request starting HTTP/1.1 GET https://[Redacted]/.well-known/openid-configuration - -
12/08/2024, 09:40:26.426 -  All hosts are allowed.
12/08/2024, 09:40:26.426 -  Adding HSTS header to response.
12/08/2024, 09:40:26.426 -  The request path /.well-known/openid-configuration does not match a supported file type
12/08/2024, 09:40:26.426 -  No candidates found for the request path '/.well-known/openid-configuration'
12/08/2024, 09:40:26.426 -  Request did not match any endpoints
12/08/2024, 09:40:26.426 -  CORS request made for path: /.well-known/openid-configuration from origin: https://[Redacted]
12/08/2024, 09:40:26.426 -  Cache hit for https://[Redacted]
12/08/2024, 09:40:26.426 -  CorsPolicyService allowed origin: https://[Redacted]
12/08/2024, 09:40:26.427 -  The request has an origin header: 'https://[Redacted]'.
12/08/2024, 09:40:26.427 -  CORS policy execution successful.
12/08/2024, 09:40:26.427 -  AuthenticationScheme: idsrv was not authenticated.
12/08/2024, 09:40:26.427 -  AuthenticationScheme: idsrv was not authenticated.
12/08/2024, 09:40:26.427 -  Request path /.well-known/openid-configuration matched to endpoint type Discovery
12/08/2024, 09:40:26.428 -  Endpoint enabled: Discovery, successfully created handler: Duende.IdentityServer.Endpoints.DiscoveryEndpoint
12/08/2024, 09:40:26.428 -  Invoking IdentityServer endpoint: Duende.IdentityServer.Endpoints.DiscoveryEndpoint for /.well-known/openid-configuration
12/08/2024, 09:40:26.428 -  Processing discovery request.
12/08/2024, 09:40:26.428 -  Start discovery request
12/08/2024, 09:40:26.428 -  Calling into discovery response generator: Duende.IdentityServer.ResponseHandling.DiscoveryResponseGenerator
12/08/2024, 09:40:26.428 -  Getting all the keys.
12/08/2024, 09:40:26.428 -  Cache hit when loading all keys.
12/08/2024, 09:40:26.428 -  Looking for active signing keys.
12/08/2024, 09:40:26.428 -  Looking for an active signing key for alg RS256.
12/08/2024, 09:40:26.428 -  Checking if key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is active (respecting activation delay).
12/08/2024, 09:40:26.428 -  Key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is inactive: the current time is prior to its activation delay.
12/08/2024, 09:40:26.428 -  Checking if key with kid DDA1ACB7B81465052B036C1C2DC59864 is active (respecting activation delay).
12/08/2024, 09:40:26.428 -  Key with kid DDA1ACB7B81465052B036C1C2DC59864 is active.
12/08/2024, 09:40:26.428 -  Active signing key found (respecting the activation delay) with kid: DDA1ACB7B81465052B036C1C2DC59864.
12/08/2024, 09:40:26.428 -  Found active signing key for alg RS256 with kid DDA1ACB7B81465052B036C1C2DC59864.
12/08/2024, 09:40:26.428 -  Checking if key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is active (respecting activation delay).
12/08/2024, 09:40:26.428 -  Key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is inactive: the current time is prior to its activation delay.
12/08/2024, 09:40:26.428 -  Checking if key with kid DDA1ACB7B81465052B036C1C2DC59864 is active (respecting activation delay).
12/08/2024, 09:40:26.428 -  Key with kid DDA1ACB7B81465052B036C1C2DC59864 is active.
12/08/2024, 09:40:26.428 -  Active signing key found (respecting the activation delay) with kid: DDA1ACB7B81465052B036C1C2DC59864.
12/08/2024, 09:40:26.429 -  Key rotation not required for alg RS256; New key expected to be created in "73.22:23:02"
12/08/2024, 09:40:26.429 -  Cache hit for __all__
12/08/2024, 09:40:26.429 -  Getting the current key.
12/08/2024, 09:40:26.429 -  Cache hit when loading all keys.
12/08/2024, 09:40:26.429 -  Looking for active signing keys.
12/08/2024, 09:40:26.429 -  Looking for an active signing key for alg RS256.
12/08/2024, 09:40:26.429 -  Checking if key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is active (respecting activation delay).
12/08/2024, 09:40:26.429 -  Key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is inactive: the current time is prior to its activation delay.
12/08/2024, 09:40:26.429 -  Checking if key with kid DDA1ACB7B81465052B036C1C2DC59864 is active (respecting activation delay).
12/08/2024, 09:40:26.429 -  Key with kid DDA1ACB7B81465052B036C1C2DC59864 is active.
12/08/2024, 09:40:26.429 -  Active signing key found (respecting the activation delay) with kid: DDA1ACB7B81465052B036C1C2DC59864.
12/08/2024, 09:40:26.429 -  Found active signing key for alg RS256 with kid DDA1ACB7B81465052B036C1C2DC59864.
12/08/2024, 09:40:26.429 -  Checking if key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is active (respecting activation delay).
12/08/2024, 09:40:26.429 -  Key with kid 6A8BD84B554DEA5B5A9FAF797D1D1736 is inactive: the current time is prior to its activation delay.
12/08/2024, 09:40:26.429 -  Checking if key with kid DDA1ACB7B81465052B036C1C2DC59864 is active (respecting activation delay).
12/08/2024, 09:40:26.431 -  Key with kid DDA1ACB7B81465052B036C1C2DC59864 is active.
12/08/2024, 09:40:26.431 -  Active signing key found (respecting the activation delay) with kid: DDA1ACB7B81465052B036C1C2DC59864.
12/08/2024, 09:40:26.431 -  Key rotation not required for alg RS256; New key expected to be created in "73.22:23:02"
12/08/2024, 09:40:26.431 -  Active signing key found with kid DDA1ACB7B81465052B036C1C2DC59864 for alg RS256. Expires in "11.22:15:08". Retires in "25.22:15:08"
12/08/2024, 09:40:26.431 -  Invoking result: Duende.IdentityServer.Endpoints.Results.DiscoveryDocumentResult
12/08/2024, 09:40:26.431 -  Request finished HTTP/1.1 GET https://[Redacted]/.well-known/openid-configuration - - - 200 - application/json;+charset=UTF-8 5.6007ms

[josephdecock]

Just wanted to update everyone that we are continuing our investigation. We don't have a fix yet unfortunately, but we'll keep you all updated as we go.

[josephdecock]

The picture that I'm getting is that

1. there is an intermittent time-out on the discovery endpoint
2. the timeout goes away after a restart
3. the timeouts always occur around UTC 12:00

Has anyone in this thread seen it happen at other times of day?

[sanket-mistry-jm]

The picture that I'm getting is that

1. there is an intermittent time-out on the discovery endpoint
2. the timeout goes away after a restart
3. the timeouts always occur around UTC 12:00

Has anyone in this thread seen it happen at other times of day?

@josephdecock , for us prettymuch all endpoints start delaying by x seconds eventually going to x minutes. in our case, /connect/authorize works fine and show login UI but post login action it times-out when the issue occurs. I am thinking may be something related to how tokens are signed, or keys are generated/regenerated?

We were able to capture .NET Profiler Trace, and we see this....

[Stumm304]

Hey @josephdecock,

we're also experiencing this issue since around two weeks now.

But we are using different versions as reported.
I also cannot confirm, that it only happens around UTC 12:00. We also had it around 5pm UTC.
In our dev environment, it sometimes happens twice a day and sometimes a couple of days nothing.
In Prod it luckily just happened once, yet.

• DEV Environment

  • Duende 7.0.6, .NET 8

• PROD Environment

  • Duende 7.0.5, .NET 8

Besides different versions and times, the issue is exactly the same as reported. Only a restart helps.

[AndersAbel]

If anyone would be able to capture Otel Traces of the timeout that could help us understand the root cause.

https://docs.duendesoftware.com/identityserver/v7/diagnostics/otel/traces/