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

TaskCanceledException during token request #541

Closed
spin973 opened this issue Nov 26, 2021 · 7 comments
Closed

TaskCanceledException during token request #541

spin973 opened this issue Nov 26, 2021 · 7 comments

Comments

@spin973
Copy link

spin973 commented Nov 26, 2021

Hi,
I've upgrade an IdentityServer4 .NET 5 to Duende 6.0.0.Preview4 .NET 6. When the client, a Blazor wasm .NET6, try to access the Api server (asp.net core 6) with an expired token and it try to refresh it, I see in the server's console an error, but the token is refreshed correctly. This happen only the first time after the server start, the following times it works without any error regularly.
The server is configured as follow:

builder.Services
    .AddIdentityServer(options =>
    {
        options.Events.RaiseErrorEvents = true;
        options.Events.RaiseInformationEvents = true;
        options.Events.RaiseFailureEvents = true;
        options.Events.RaiseSuccessEvents = true;
    })
    .AddConfigurationStoreCache()
    .AddConfigurationStore(options =>
    {
        options.ConfigureDbContext = build => build.UseDatabaseFromConfiguration(builder);
        options.DefaultSchema = "IdentityServer";     
    })
    .AddOperationalStore(options =>
    {
        options.ConfigureDbContext = build => build.UseDatabaseFromConfiguration(builder);
        options.DefaultSchema = "IdentityServer"; 
        options.EnableTokenCleanup = true;
        options.TokenCleanupInterval = 3600;
    })
    .AddAspNetIdentity<IdentityUserEntity>()
    .AddProfileService<ProfileService>();

this is the log on the server's console (this is the part after I try to access with an expired token):

18:49:54 [Debug] Duende.IdentityServer.Hosting.EndpointRouter
Request path /connect/authorize matched to endpoint type Authorize

18:49:54 [Debug] Duende.IdentityServer.Hosting.EndpointRouter
Endpoint enabled: Authorize, successfully created handler: Duende.IdentityServer.Endpoints.AuthorizeEndpoint

18:49:54 [Information] Duende.IdentityServer.Hosting.IdentityServerMiddleware
Invoking IdentityServer endpoint: Duende.IdentityServer.Endpoints.AuthorizeEndpoint for /connect/authorize

18:49:54 [Debug] Duende.IdentityServer.Endpoints.AuthorizeEndpoint
Start authorize request

18:49:54 [Debug] Duende.IdentityServer.Endpoints.AuthorizeEndpoint
User in authorize request: 2

18:49:54 [Debug] Duende.IdentityServer.Validation.AuthorizeRequestValidator
Start authorize request protocol validation

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ClientStore
Client.Id found in database: True

18:49:54 [Debug] Duende.IdentityServer.Stores.ValidatingClientStore
client configuration validation for client Client.Id succeeded.

18:49:54 [Debug] Duende.IdentityServer.Validation.AuthorizeRequestValidator
Checking for PKCE parameters

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ResourceStore
Found [] identity scopes in database

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ResourceStore
Found ["API.Resource"] API resources in database

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ResourceStore
Found ["API.Resource.Scope"] scopes in database

18:49:54 [Debug] Duende.IdentityServer.Validation.AuthorizeRequestValidator
Calling into custom validator: Duende.IdentityServer.Validation.DefaultCustomAuthorizeRequestValidator

18:49:54 [Debug] Duende.IdentityServer.Endpoints.AuthorizeEndpoint
ValidatedAuthorizeRequest
{"ClientId": "Client.Id", "ClientName": "Client.Name", "RedirectUri": "https://localhost:5010/authentication/login-callback", "AllowedRedirectUris": ["https://localhost:5010/authentication/login-callback"], "SubjectId": "2", "ResponseType": "code", "ResponseMode": "query", "GrantType": "authorization_code", "RequestedScopes": "API.Resource.Scope", "State": "56192157013f46859337d71751ec91ab", "UiLocales": null, "Nonce": null, "AuthenticationContextReferenceClasses": null, "DisplayMode": null, "PromptMode": "none", "MaxAge": null, "LoginHint": null, "SessionId": "31F36E2A70FC7DD614963B2EEAA673A1", "Raw": {"client_id": "Client.Id", "redirect_uri": "https://localhost:5010/authentication/login-callback", "response_type": "code", "scope": "API.Resource.Scope", "state": "56192157013f46859337d71751ec91ab", "code_challenge": "nFi9yJ75zU0z4o6OFGN-a5ucbuv7WtI7GGDSPYezUuM", "code_challenge_method": "S256", "prompt": "none", "id_token_hint": "REDACTED", "response_mode": "query"}, "$type": "AuthorizeRequestValidationLog"}

18:49:54 [Debug] Duende.IdentityServer.Services.DefaultConsentService
Client is configured to not require consent, no consent is required

18:49:54 [Debug] Duende.IdentityServer.ResponseHandling.AuthorizeResponseGenerator
Creating Authorization Code Flow response.

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore
527F118020710355B53C73D30B51F7D36A4E74196321760BB4838772BB772E19 not found in database

18:49:54 [Information] Duende.IdentityServer.Events.DefaultEventService
{"ClientId": "Client.Id", "ClientName": "Client.Name", "RedirectUri": "https://localhost:5010/authentication/login-callback", "Endpoint": "Authorize", "SubjectId": "2", "Scopes": "API.Resource.Scope", "GrantType": "authorization_code", "Tokens": [{"TokenType": "code", "TokenValue": "****2D-1", "$type": "Token"}], "Category": "Token", "Name": "Token Issued Success", "EventType": "Success", "Id": 2000, "Message": null, "ActivityId": "0HMDH0J9USHF2:0000000F", "TimeStamp": "2021-11-26T17:49:54.0000000Z", "ProcessId": 19028, "LocalIpAddress": "::1:5000", "RemoteIpAddress": "::1", "$type": "TokenIssuedSuccessEvent"}

18:49:54 [Debug] Duende.IdentityServer.Endpoints.AuthorizeEndpoint
Authorize endpoint response
{"SubjectId": "2", "ClientId": "Client.Id", "RedirectUri": "https://localhost:5010/authentication/login-callback", "State": "56192157013f46859337d71751ec91ab", "Scope": "API.Resource.Scope", "Error": null, "ErrorDescription": null, "$type": "AuthorizeResponseLog"}

18:49:54 [Debug] Duende.IdentityServer.Hosting.CorsPolicyProvider
CORS request made for path: /.well-known/openid-configuration from origin: https://localhost:5010

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Services.CorsPolicyService
Origin https://localhost:5010 is allowed: True

18:49:54 [Debug] Duende.IdentityServer.Hosting.CorsPolicyProvider
CorsPolicyService allowed origin: https://localhost:5010

18:49:54 [Debug] Duende.IdentityServer.Hosting.EndpointRouter
Request path /.well-known/openid-configuration matched to endpoint type Discovery

18:49:54 [Debug] Duende.IdentityServer.Hosting.EndpointRouter
Endpoint enabled: Discovery, successfully created handler: Duende.IdentityServer.Endpoints.DiscoveryEndpoint

18:49:54 [Information] Duende.IdentityServer.Hosting.IdentityServerMiddleware
Invoking IdentityServer endpoint: Duende.IdentityServer.Endpoints.DiscoveryEndpoint for /.well-known/openid-configuration

18:49:54 [Debug] Duende.IdentityServer.Endpoints.DiscoveryEndpoint
Start discovery request

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Getting all the keys.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Cache hit when loading all keys.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Looking for active signing keys.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Looking for an active signing key for alg RS256.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
No active signing key found (respecting the activation delay).

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Active signing key found (ignoring the activation delay) with kid: 9ABFD13811BFCC290D252F27B495B373.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Found active signing key for alg RS256 with kid 9ABFD13811BFCC290D252F27B495B373.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
No active signing key found (respecting the activation delay).

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Active signing key found (ignoring the activation delay) with kid: 9ABFD13811BFCC290D252F27B495B373.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Key rotation not required for alg RS256; New key expected to be created in 74.22:57:07

18:49:54 [Debug] Duende.IdentityServer.Hosting.CorsPolicyProvider
CORS request made for path: /connect/token from origin: https://localhost:5010

18:49:54 [Error] Microsoft.EntityFrameworkCore.Database.Connection
An error occurred using the connection to database 'IdentityServerDB.NET6' on server 'SERVER\SQLEXPRESS'.

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Services.CorsPolicyService
Origin https://localhost:5010 is allowed: True

18:49:54 [Error] Microsoft.EntityFrameworkCore.Query
An exception occurred while iterating over the results of a query for context type 'Duende.IdentityServer.EntityFramework.DbContexts.ConfigurationDbContext'.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.MoveNextAsync()
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.MoveNextAsync()

18:49:54 [Debug] Duende.IdentityServer.Hosting.CorsPolicyProvider
CorsPolicyService allowed origin: https://localhost:5010

18:49:54 [Debug] Duende.IdentityServer.Hosting.EndpointRouter
Request path /connect/token matched to endpoint type Token

18:49:54 [Information] Duende.IdentityServer.Events.DefaultEventService
{"Details": "System.Threading.Tasks.TaskCanceledException: A task was canceled.\r\n at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)\r\n at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.MoveNextAsync()\r\n at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable1 source, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable1 source, CancellationToken cancellationToken)\r\n at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToArrayAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)\r\n at Duende.IdentityServer.EntityFramework.Stores.ResourceStore.GetAllResourcesAsync() in //src/EntityFramework.Storage/Stores/ResourceStore.cs:line 198\r\n at Duende.IdentityServer.Stores.IResourceStoreExtensions.GetAllEnabledResourcesAsync(IResourceStore store) in //src/IdentityServer/Extensions/IResourceStoreExtensions.cs:line 108\r\n at Duende.IdentityServer.ResponseHandling.DiscoveryResponseGenerator.CreateDiscoveryDocumentAsync(String baseUrl, String issuerUri) in //src/IdentityServer/ResponseHandling/Default/DiscoveryResponseGenerator.cs:line 224\r\n at Duende.IdentityServer.Endpoints.DiscoveryEndpoint.ProcessAsync(HttpContext context) in //src/IdentityServer/Endpoints/DiscoveryEndpoint.cs:line 63\r\n at Duende.IdentityServer.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IIssuerNameService issuerNameService, IBackChannelLogoutService backChannelLogoutService) in /_/src/IdentityServer/Hosting/IdentityServerMiddleware.cs:line 84", "Category": "Error", "Name": "Unhandled Exception", "EventType": "Error", "Id": 3000, "Message": "A task was canceled.", "ActivityId": "0HMDH0J9USHF3:00000017", "TimeStamp": "2021-11-26T17:49:54.0000000Z", "ProcessId": 19028, "LocalIpAddress": "::1:5000", "RemoteIpAddress": "::1", "$type": "UnhandledExceptionEvent"}

18:49:54 [Fatal] Duende.IdentityServer.Hosting.IdentityServerMiddleware
Unhandled exception: A task was canceled.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.MoveNextAsync()
at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable1 source, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable1 source, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToArrayAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)
at Duende.IdentityServer.EntityFramework.Stores.ResourceStore.GetAllResourcesAsync() in //src/EntityFramework.Storage/Stores/ResourceStore.cs:line 198
at Duende.IdentityServer.Stores.IResourceStoreExtensions.GetAllEnabledResourcesAsync(IResourceStore store) in //src/IdentityServer/Extensions/IResourceStoreExtensions.cs:line 108
at Duende.IdentityServer.ResponseHandling.DiscoveryResponseGenerator.CreateDiscoveryDocumentAsync(String baseUrl, String issuerUri) in //src/IdentityServer/ResponseHandling/Default/DiscoveryResponseGenerator.cs:line 224
at Duende.IdentityServer.Endpoints.DiscoveryEndpoint.ProcessAsync(HttpContext context) in //src/IdentityServer/Endpoints/DiscoveryEndpoint.cs:line 63
at Duende.IdentityServer.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IIssuerNameService issuerNameService, IBackChannelLogoutService backChannelLogoutService) in /_/src/IdentityServer/Hosting/IdentityServerMiddleware.cs:line 84

18:49:54 [Debug] Duende.IdentityServer.Hosting.EndpointRouter
Endpoint enabled: Token, successfully created handler: Duende.IdentityServer.Endpoints.TokenEndpoint

18:49:54 [Information] Duende.IdentityServer.Hosting.IdentityServerMiddleware
Invoking IdentityServer endpoint: Duende.IdentityServer.Endpoints.TokenEndpoint for /connect/token

18:49:54 [Error] Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware
An unhandled exception has occurred while executing the request.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)
at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func4 operation, Func4 verifySucceeded, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable1.AsyncEnumerator.MoveNextAsync()
at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable1 source, CancellationToken cancellationToken) at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable1 source, CancellationToken cancellationToken)
at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToArrayAsync[TSource](IQueryable1 source, CancellationToken cancellationToken) at Duende.IdentityServer.EntityFramework.Stores.ResourceStore.GetAllResourcesAsync() in /_/src/EntityFramework.Storage/Stores/ResourceStore.cs:line 198 at Duende.IdentityServer.Stores.IResourceStoreExtensions.GetAllEnabledResourcesAsync(IResourceStore store) in /_/src/IdentityServer/Extensions/IResourceStoreExtensions.cs:line 108 at Duende.IdentityServer.ResponseHandling.DiscoveryResponseGenerator.CreateDiscoveryDocumentAsync(String baseUrl, String issuerUri) in /_/src/IdentityServer/ResponseHandling/Default/DiscoveryResponseGenerator.cs:line 224 at Duende.IdentityServer.Endpoints.DiscoveryEndpoint.ProcessAsync(HttpContext context) in /_/src/IdentityServer/Endpoints/DiscoveryEndpoint.cs:line 63 at Duende.IdentityServer.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IIssuerNameService issuerNameService, IBackChannelLogoutService backChannelLogoutService) in /_/src/IdentityServer/Hosting/IdentityServerMiddleware.cs:line 84 at Duende.IdentityServer.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IIssuerNameService issuerNameService, IBackChannelLogoutService backChannelLogoutService) in /_/src/IdentityServer/Hosting/IdentityServerMiddleware.cs:line 99 at Duende.IdentityServer.Hosting.MutualTlsEndpointMiddleware.Invoke(HttpContext context, IAuthenticationSchemeProvider schemes) in /_/src/IdentityServer/Hosting/MutualTlsEndpointMiddleware.cs:line 94 at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context) at Duende.IdentityServer.Hosting.DynamicProviders.DynamicSchemeAuthenticationMiddleware.Invoke(HttpContext context) in /_/src/IdentityServer/Hosting/DynamicProviders/DynamicSchemes/DynamicSchemeAuthenticationMiddleware.cs:line 47 at Microsoft.AspNetCore.Cors.Infrastructure.CorsMiddleware.<Invoke>g__InvokeCoreAwaited|15_0(HttpContext context, Task1 policyTask)
at Duende.IdentityServer.Hosting.BaseUrlMiddleware.Invoke(HttpContext context) in /_/src/IdentityServer/Hosting/BaseUrlMiddleware.cs:line 28
at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)

18:49:54 [Debug] Duende.IdentityServer.Endpoints.TokenEndpoint
Start token request.

18:49:54 [Debug] Duende.IdentityServer.Validation.ClientSecretValidator
Start client validation

18:49:54 [Debug] Duende.IdentityServer.Validation.BasicAuthenticationSecretParser
Start parsing Basic Authentication secret

18:49:54 [Debug] Duende.IdentityServer.Validation.PostBodySecretParser
Start parsing for secret in post body

18:49:54 [Debug] Duende.IdentityServer.Validation.PostBodySecretParser
client id without secret found

18:49:54 [Debug] Duende.IdentityServer.Validation.ISecretsListParser
Parser found secret: PostBodySecretParser

18:49:54 [Debug] Duende.IdentityServer.Validation.ISecretsListParser
Secret id found: Client.Id

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ClientStore
Client.Id found in database: True

18:49:54 [Debug] Duende.IdentityServer.Stores.ValidatingClientStore
client configuration validation for client Client.Id succeeded.

18:49:54 [Debug] Duende.IdentityServer.Validation.ClientSecretValidator
Public Client - skipping secret validation success

18:49:54 [Debug] Duende.IdentityServer.Validation.ClientSecretValidator
Client validation success

18:49:54 [Information] Duende.IdentityServer.Events.DefaultEventService
{"ClientId": "Client.Id", "AuthenticationMethod": "NoSecret", "Category": "Authentication", "Name": "Client Authentication Success", "EventType": "Success", "Id": 1010, "Message": null, "ActivityId": "0HMDH0J9USHF3:00000019", "TimeStamp": "2021-11-26T17:49:54.0000000Z", "ProcessId": 19028, "LocalIpAddress": "::1:5000", "RemoteIpAddress": "::1", "$type": "ClientAuthenticationSuccessEvent"}

18:49:54 [Debug] Duende.IdentityServer.Validation.TokenRequestValidator
Start token request validation

18:49:54 [Debug] Duende.IdentityServer.Validation.TokenRequestValidator
Start validation of authorization code token request

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore
527F118020710355B53C73D30B51F7D36A4E74196321760BB4838772BB772E19 found in database: True

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.PersistedGrantStore
removing 527F118020710355B53C73D30B51F7D36A4E74196321760BB4838772BB772E19 persisted grant from database

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ResourceStore
Found [] identity scopes in database

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ResourceStore
Found ["API.Resource"] API resources in database

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ResourceStore
Found ["API.Resource.Scope"] scopes in database

18:49:54 [Debug] Duende.IdentityServer.Validation.TokenRequestValidator
Client required a proof key for code exchange. Starting PKCE validation

18:49:54 [Debug] Duende.IdentityServer.Validation.TokenRequestValidator
Validation of authorization code token request success

18:49:54 [Information] Duende.IdentityServer.Validation.TokenRequestValidator
Token request validation success, {"ClientId": "Client.Id", "ClientName": "Client.Name", "GrantType": "authorization_code", "Scopes": null, "AuthorizationCode": "****2D-1", "RefreshToken": "********", "UserName": null, "AuthenticationContextReferenceClasses": null, "Tenant": null, "IdP": null, "Raw": {"client_id": "Client.Id", "code": "0423B485044B9602A15E2FA4168833FF7BD6A77ED85DEEFFE2A6DD07A26A062D-1", "redirect_uri": "https://localhost:5010/authentication/login-callback", "code_verifier": "cba15df761cd4083b2aa862a52d6a850f610479d199c4772b1b3a43bdb3755c485d711288bbb4ca48c47d5b56739258c", "grant_type": "authorization_code"}, "$type": "TokenRequestValidationLog"}

18:49:54 [Debug] Duende.IdentityServer.EntityFramework.Stores.ClientStore
Client.Id found in database: True

18:49:54 [Debug] Duende.IdentityServer.Stores.ValidatingClientStore
client configuration validation for client Client.Id succeeded.

18:49:54 [Debug] Duende.IdentityServer.Services.DefaultClaimsService
Getting claims for access token for client: Client.Id

18:49:54 [Debug] Duende.IdentityServer.Services.DefaultClaimsService
Getting claims for access token for subject: 2

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Getting the current key.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Cache hit when loading all keys.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Looking for active signing keys.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Looking for an active signing key for alg RS256.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
No active signing key found (respecting the activation delay).

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Active signing key found (ignoring the activation delay) with kid: 9ABFD13811BFCC290D252F27B495B373.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Found active signing key for alg RS256 with kid 9ABFD13811BFCC290D252F27B495B373.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
No active signing key found (respecting the activation delay).

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Active signing key found (ignoring the activation delay) with kid: 9ABFD13811BFCC290D252F27B495B373.

18:49:54 [Debug] Duende.IdentityServer.Services.KeyManagement.KeyManager
Key rotation not required for alg RS256; New key expected to be created in 74.22:57:07

18:49:54 [Information] Duende.IdentityServer.Services.KeyManagement.KeyManager
Active signing key found with kid 9ABFD13811BFCC290D252F27B495B373 for alg RS256. Expires in 88.22:57:07. Retires in 102.22:57:07

18:49:54 [Information] Duende.IdentityServer.Events.DefaultEventService
{"ClientId": "Client.Id", "ClientName": "Client.Name", "RedirectUri": null, "Endpoint": "Token", "SubjectId": "2", "Scopes": "API.Resource.Scope", "GrantType": "authorization_code", "Tokens": [{"TokenType": "access_token", "TokenValue": "****WUvw", "$type": "Token"}], "Category": "Token", "Name": "Token Issued Success", "EventType": "Success", "Id": 2000, "Message": null, "ActivityId": "0HMDH0J9USHF3:00000019", "TimeStamp": "2021-11-26T17:49:54.0000000Z", "ProcessId": 19028, "LocalIpAddress": "::1:5000", "RemoteIpAddress": "::1", "$type": "TokenIssuedSuccessEvent"}

18:49:54 [Debug] Duende.IdentityServer.Endpoints.TokenEndpoint
Token request success.
@brockallen
Copy link
Member

Hi @spin973. I wasn't able to repo this. The client app is all WASM (meaning all browser-based)? What library are you using to execute the token request?

The exception call stack seems to indicate that this is happening in the request for the discovery document, and seems to hint that the HTTP connection was closed in the middle of the DB lookup from the resource store to get the scopes for the metadata. That feels like the browser might be loading a new page, thus it closes its outbound HTTP call to the discovery endpoint. Might this explain what's happening?

@brockallen
Copy link
Member

brockallen commented Nov 30, 2021 •
edited
Loading

I actually played around a bit and was able to repo your issue (it was pretty much my guess above). We are now using the cancellation token from the http context in the calls into the EF layer, which is why you're now seeing this behavior. We don't handle this scenario to prevent an "error" in the logs, but it's something we can think about and possibly add.

Unfortunately, no matter what we do, EF itself always logs this internally:

dotnet/efcore#19526

Which still makes for an alarming (and false positive) error in the log. Not sure what we can do about it, given that it's an open issue in the EF repo.

@brockallen
Copy link
Member

Quick PR to show what I'd propose we do in this situation: #550

@spin973
Copy link
Author

spin973 commented Dec 1, 2021

Thanks @brockallen, I too did a simple repo to reproduce the error (https://github.com/spin973/IS6-Test.git) what I don't understand is why it only occurs once after starting dell 'application. Your answer explains to me why this does not happen with IS4. This is not a problem because the token is still successfully released, but in my opinion your proposal to create a log instead of leaving the exception makes the application log more readable in looking for possible problems.

@brockallen
Copy link
Member

According to the EFCore team, this won't be fixed until their EF Core v7 release. So you will have to live with those occasional errors in the logs, or add a filter on the logging system to filter that specific message out.

@brockallen
Copy link
Member

brockallen commented Dec 10, 2021 •
edited
Loading

Hmm... the more I think about it, the more this seems like a larger issue that we can't (or shouldn't) wrap with our own exception filter. Mainly because if you look at this post there are many different conditions that could be the same. So I don't want to go down the path of putting such a complicated filter in our middleware. It feels like perhaps better to be done by the hosting app.

What do you think, @spin973?

@spin973
Copy link
Author

spin973 commented Dec 10, 2021

I'm not an expert, but I think putting such a filter on the server is not a good thing. For me, waiting for them to fix the problem with v7.0, I keep the log with these exceptions. Thank you.

@spin973 spin973 closed this as completed Dec 10, 2021
@Stra1ghter Stra1ghter mentioned this issue Oct 7, 2022
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
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@brockallen @spin973