abp Cannot relogin: pressing Login button stucks - seems like Identity Server issue

ABP 5.1.2 / Angular / Ef Core / separate Identity Server

Hi. Time to time I am getting stuck on requests to my back-end. There is no information in the API logs, it all just hangs and nothing is happening. This time I was able to reproduce such issue when accidently pressing "Back" in my browser and moving away from my application. Then I pressed forward - moved back to it, but got "non authorized" exception 401. I reloaded the page and was redirected to Login page. But when I press "Login" button - nothing happens, there's just a spinning wheel. If I clean cookies and storage in browser for my app - it is all the same. But the suspicious exception which I can see is the same as in all the situations when I am getting stuck on requests:

Could you please suggest what may cause this and how to overcome it?

This is really important. Once I understand the root cause - probably I will be able to resolve all my issues with hanging requests. Could it be ABP bug?

May 21 '22 16:05 alexandis

hi

We need the steps to reproduce the problem and get the full error log.

May 23 '22 02:05 maliming

Hi.

Too bad. I was unable to reproduce the bug for the second time, probably I am missing some details this time. If the following log from Identity Server from that day doesn't help - I'll have to close the bug, unfortunately.

But i would be really greatful, if you at least suggest where I need to dig in - what may cause such error, since it's exception inside your code and you have better understanding of how it functions inside. We have some custom processing, but I cannot send the test project, alas.

So short note again: when this issue happens - I cannot work with the front-end anymore until I restart backend (API host+ Identity server: looks like a deadlock or something, but seems like not a DB issue):

2022-05-18 16:34:05.623 +03:00 [INF] Request starting HTTP/1.1 OPTIONS https://localhost:44357/connect/token - - 2022-05-18 16:34:05.624 +03:00 [INF] CORS policy execution successful. 2022-05-18 16:34:05.625 +03:00 [INF] Request finished HTTP/1.1 OPTIONS https://localhost:44357/connect/token - - - 204 - - 1.8114ms 2022-05-18 16:34:05.626 +03:00 [INF] Request starting HTTP/1.1 POST https://localhost:44357/connect/token application/x-www-form-urlencoded 214 2022-05-18 16:34:05.627 +03:00 [INF] CORS policy execution successful. 2022-05-18 16:34:05.632 +03:00 [INF] Failed to validate the token. Microsoft.IdentityModel.Tokens.SecurityTokenExpiredException: IDX10223: Lifetime validation failed. The token is expired. ValidTo: '5/18/2022 1:00:45 PM', Current time: '5/18/2022 1:34:05 PM'. at Microsoft.IdentityModel.Tokens.Validators.ValidateLifetime(Nullable1 notBefore, Nullable1 expires, SecurityToken securityToken, TokenValidationParameters validationParameters) at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateTokenPayload(JwtSecurityToken jwtToken, TokenValidationParameters validationParameters) at System.IdentityModel.Tokens.Jwt.JwtSecurityTokenHandler.ValidateToken(String token, TokenValidationParameters validationParameters, SecurityToken& validatedToken) at Microsoft.AspNetCore.Authentication.JwtBearer.JwtBearerHandler.HandleAuthenticateAsync() 2022-05-18 16:34:05.633 +03:00 [INF] Bearer was not authenticated. Failure message: IDX10223: Lifetime validation failed. The token is expired. ValidTo: '5/18/2022 1:00:45 PM', Current time: '5/18/2022 1:34:05 PM'. 2022-05-18 16:34:06.389 +03:00 [DBG] CORS request made for path: /connect/token from origin: https://localhost:4201 2022-05-18 16:34:06.505 +03:00 [WRN] Origin is not allowed: https://localhost:4201 2022-05-18 16:34:06.505 +03:00 [WRN] CorsPolicyService did not allow origin: https://localhost:4201 2022-05-18 16:34:06.505 +03:00 [INF] No CORS policy found for the specified request. 2022-05-18 16:34:06.506 +03:00 [DBG] Request path /connect/token matched to endpoint type Token 2022-05-18 16:34:06.528 +03:00 [DBG] Endpoint enabled: Token, successfully created handler: IdentityServer4.Endpoints.TokenEndpoint 2022-05-18 16:34:06.528 +03:00 [INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.TokenEndpoint for /connect/token 2022-05-18 16:34:06.528 +03:00 [DBG] Start token request. 2022-05-18 16:34:06.528 +03:00 [DBG] Start client validation 2022-05-18 16:34:06.528 +03:00 [DBG] Start parsing Basic Authentication secret 2022-05-18 16:34:06.528 +03:00 [DBG] Start parsing for secret in post body 2022-05-18 16:34:06.528 +03:00 [DBG] Parser found secret: PostBodySecretParser 2022-05-18 16:34:06.528 +03:00 [DBG] Secret id found: MasterData_App 2022-05-18 16:34:07.156 +03:00 [DBG] client configuration validation for client MasterData_App succeeded. 2022-05-18 16:34:07.156 +03:00 [DBG] Public Client - skipping secret validation success 2022-05-18 16:34:07.156 +03:00 [DBG] Client validation success 2022-05-18 16:34:07.156 +03:00 [INF] {"ClientId":"MasterData_App","AuthenticationMethod":"SharedSecret","Category":"Authentication","Name":"Client Authentication Success","EventType":"Success","Id":1010,"Message":null,"ActivityId":"8000005c-0004-fe00-b63f-84710c7967bb","TimeStamp":"2022-05-18T13:34:07.0000000Z","ProcessId":38000,"LocalIpAddress":"::1:44357","RemoteIpAddress":"::1","$type":"ClientAuthenticationSuccessEvent"} 2022-05-18 16:34:07.156 +03:00 [DBG] Start token request validation 2022-05-18 16:34:07.157 +03:00 [DBG] Start validation of refresh token request 2022-05-18 16:34:08.298 +03:00 [INF] {"Details":"System.OperationCanceledException: The operation was canceled.\r\n at System.Threading.CancellationToken.ThrowOperationCanceledException()\r\n at Volo.Abp.Identity.IdentityUserStore.FindByIdAsync(String userId, CancellationToken cancellationToken)\r\n at Castle.Proxies.Invocations.UserManager1_FindByIdAsync.InvokeMethodOnTarget()\r\n at Castle.DynamicProxy.AbstractInvocation.Proceed()\r\n at Castle.DynamicProxy.AbstractInvocation.ProceedInfo.Invoke()\r\n at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo)\r\n at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapterWithReturnValue1.ProceedAsync()\r\n at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation)\r\n at Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter1.InterceptAsync[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo, Func3 proceed)\r\n at IdentityServer4.AspNetIdentity.ProfileService1.FindUserAsync(String subjectId)\r\n at IdentityServer4.AspNetIdentity.ProfileService1.IsActiveAsync(IsActiveContext context, String subjectId)\r\n at IdentityServer4.AspNetIdentity.ProfileService1.IsActiveAsync(IsActiveContext context)\r\n at Volo.Abp.IdentityServer.AspNetIdentity.AbpProfileService.IsActiveAsync(IsActiveContext context)\r\n at AbxEps.CentralTools.IdentityServer.Profile.AbxProfileService.IsActiveAsync(IsActiveContext context) in D:\\CT\\AbxEps.CentralTools\\aspnet-core\\src\\AbxEps.CentralTools.IdentityServer\\IdentityServer\\Profile\\AbxProfileService.cs:line 79\r\n at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous(IInvocation invocation, IInvocationProceedInfo proceedInfo)\r\n at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapter.ProceedAsync()\r\n at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation)\r\n at Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter1.InterceptAsync(IInvocation invocation, IInvocationProceedInfo proceedInfo, Func3 proceed)\r\n at IdentityServer4.Services.DefaultRefreshTokenService.ValidateRefreshTokenAsync(String tokenHandle, Client client)\r\n at IdentityServer4.Validation.TokenRequestValidator.ValidateRefreshTokenRequestAsync(NameValueCollection parameters)\r\n at IdentityServer4.Validation.TokenRequestValidator.RunValidationAsync(Func2 validationFunc, NameValueCollection parameters)\r\n at IdentityServer4.Validation.TokenRequestValidator.ValidateRequestAsync(NameValueCollection parameters, ClientSecretValidationResult clientValidationResult)\r\n at IdentityServer4.Endpoints.TokenEndpoint.ProcessTokenRequestAsync(HttpContext context)\r\n at IdentityServer4.Endpoints.TokenEndpoint.ProcessAsync(HttpContext context)\r\n at IdentityServer4.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IBackChannelLogoutService backChannelLogoutService)","Category":"Error","Name":"Unhandled Exception","EventType":"Error","Id":3000,"Message":"The operation was canceled.","ActivityId":"8000005c-0004-fe00-b63f-84710c7967bb","TimeStamp":"2022-05-18T13:34:08.0000000Z","ProcessId":38000,"LocalIpAddress":"::1:44357","RemoteIpAddress":"::1","$type":"UnhandledExceptionEvent"} 2022-05-18 16:34:08.298 +03:00 [FTL] Unhandled exception: The operation was canceled. System.OperationCanceledException: The operation was canceled. at System.Threading.CancellationToken.ThrowOperationCanceledException() at Volo.Abp.Identity.IdentityUserStore.FindByIdAsync(String userId, CancellationToken cancellationToken) at Castle.Proxies.Invocations.UserManager1_FindByIdAsync.InvokeMethodOnTarget() at Castle.DynamicProxy.AbstractInvocation.Proceed() at Castle.DynamicProxy.AbstractInvocation.ProceedInfo.Invoke() at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo) at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapterWithReturnValue1.ProceedAsync() at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation) at Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter1.InterceptAsync[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo, Func3 proceed) at IdentityServer4.AspNetIdentity.ProfileService1.FindUserAsync(String subjectId) at IdentityServer4.AspNetIdentity.ProfileService1.IsActiveAsync(IsActiveContext context, String subjectId) at IdentityServer4.AspNetIdentity.ProfileService1.IsActiveAsync(IsActiveContext context) at Volo.Abp.IdentityServer.AspNetIdentity.AbpProfileService.IsActiveAsync(IsActiveContext context) at AbxEps.CentralTools.IdentityServer.Profile.AbxProfileService.IsActiveAsync(IsActiveContext context) in D:\CT\AbxEps.CentralTools\aspnet-core\src\AbxEps.CentralTools.IdentityServer\IdentityServer\Profile\AbxProfileService.cs:line 79 at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous(IInvocation invocation, IInvocationProceedInfo proceedInfo) at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapter.ProceedAsync() at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation) at Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter1.InterceptAsync(IInvocation invocation, IInvocationProceedInfo proceedInfo, Func3 proceed) at IdentityServer4.Services.DefaultRefreshTokenService.ValidateRefreshTokenAsync(String tokenHandle, Client client) at IdentityServer4.Validation.TokenRequestValidator.ValidateRefreshTokenRequestAsync(NameValueCollection parameters) at IdentityServer4.Validation.TokenRequestValidator.RunValidationAsync(Func2 validationFunc, NameValueCollection parameters) at IdentityServer4.Validation.TokenRequestValidator.ValidateRequestAsync(NameValueCollection parameters, ClientSecretValidationResult clientValidationResult) at IdentityServer4.Endpoints.TokenEndpoint.ProcessTokenRequestAsync(HttpContext context) at IdentityServer4.Endpoints.TokenEndpoint.ProcessAsync(HttpContext context) at IdentityServer4.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IBackChannelLogoutService backChannelLogoutService) 2022-05-18 16:34:08.399 +03:00 [ERR] An unhandled exception has occurred while executing the request. System.OperationCanceledException: The operation was canceled. at System.Threading.CancellationToken.ThrowOperationCanceledException() at Volo.Abp.Identity.IdentityUserStore.FindByIdAsync(String userId, CancellationToken cancellationToken) at Castle.Proxies.Invocations.UserManager1_FindByIdAsync.InvokeMethodOnTarget() at Castle.DynamicProxy.AbstractInvocation.Proceed() at Castle.DynamicProxy.AbstractInvocation.ProceedInfo.Invoke() at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo) at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapterWithReturnValue1.ProceedAsync() at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation) at Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter1.InterceptAsync[TResult](IInvocation invocation, IInvocationProceedInfo proceedInfo, Func3 proceed) at IdentityServer4.AspNetIdentity.ProfileService1.FindUserAsync(String subjectId) at IdentityServer4.AspNetIdentity.ProfileService1.IsActiveAsync(IsActiveContext context, String subjectId) at IdentityServer4.AspNetIdentity.ProfileService1.IsActiveAsync(IsActiveContext context) at Volo.Abp.IdentityServer.AspNetIdentity.AbpProfileService.IsActiveAsync(IsActiveContext context) at AbxEps.CentralTools.IdentityServer.Profile.AbxProfileService.IsActiveAsync(IsActiveContext context) in D:\CT\AbxEps.CentralTools\aspnet-core\src\AbxEps.CentralTools.IdentityServer\IdentityServer\Profile\AbxProfileService.cs:line 79 at Castle.DynamicProxy.AsyncInterceptorBase.ProceedAsynchronous(IInvocation invocation, IInvocationProceedInfo proceedInfo) at Volo.Abp.Castle.DynamicProxy.CastleAbpMethodInvocationAdapter.ProceedAsync() at Volo.Abp.Uow.UnitOfWorkInterceptor.InterceptAsync(IAbpMethodInvocation invocation) at Volo.Abp.Castle.DynamicProxy.CastleAsyncAbpInterceptorAdapter1.InterceptAsync(IInvocation invocation, IInvocationProceedInfo proceedInfo, Func3 proceed) at IdentityServer4.Services.DefaultRefreshTokenService.ValidateRefreshTokenAsync(String tokenHandle, Client client) at IdentityServer4.Validation.TokenRequestValidator.ValidateRefreshTokenRequestAsync(NameValueCollection parameters) at IdentityServer4.Validation.TokenRequestValidator.RunValidationAsync(Func2 validationFunc, NameValueCollection parameters) at IdentityServer4.Validation.TokenRequestValidator.ValidateRequestAsync(NameValueCollection parameters, ClientSecretValidationResult clientValidationResult) at IdentityServer4.Endpoints.TokenEndpoint.ProcessTokenRequestAsync(HttpContext context) at IdentityServer4.Endpoints.TokenEndpoint.ProcessAsync(HttpContext context) at IdentityServer4.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IBackChannelLogoutService backChannelLogoutService) at IdentityServer4.Hosting.IdentityServerMiddleware.Invoke(HttpContext context, IEndpointRouter router, IUserSession session, IEventService events, IBackChannelLogoutService backChannelLogoutService) at IdentityServer4.Hosting.MutualTlsEndpointMiddleware.Invoke(HttpContext context, IAuthenticationSchemeProvider schemes) at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context) at IdentityServer4.Hosting.BaseUrlMiddleware.Invoke(HttpContext context) at AbxEps.CentralTools.Middlewares.TenantSwitchMiddleware.InvokeAsync(HttpContext httpContext, IAbxRequestContext requestContext, IdentityUserManager userManager) in D:\CT\AbxEps.CentralTools\aspnet-core\src\AbxEps.CentralTools.IdentityServer\Middlewares\TenantSwitchMiddleware.cs:line 49 at AbxEps.CentralTools.Middlewares.SessionEndAuditingMiddleware.InvokeAsync(HttpContext httpContext, IAbxRequestContext requestContext, IdentityUserManager userManager) in D:\CT\AbxEps.CentralTools\aspnet-core\src\AbxEps.CentralTools.IdentityServer\Middlewares\SessionEndAuditingMiddleware.cs:line 45 at Volo.Abp.AspNetCore.Uow.AbpUnitOfWorkMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext() --- End of stack trace from previous location --- at Volo.Abp.AspNetCore.ExceptionHandling.AbpExceptionHandlingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Volo.Abp.AspNetCore.ExceptionHandling.AbpExceptionHandlingMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext() --- End of stack trace from previous location --- at Volo.Abp.AspNetCore.MultiTenancy.MultiTenancyMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.AspNetCore.Builder.ApplicationBuilderAbpJwtTokenMiddlewareExtension.<>c__DisplayClass0_0.<<UseJwtTokenMiddleware>b__0>d.MoveNext() --- End of stack trace from previous location --- at AbxEps.Middleware.CookieAccessToken.Extensions.IApplicationBuilderExtension.<>c__DisplayClass1_0.<<UseCookieAccessTokenDelete>b__0>d.MoveNext() --- End of stack trace from previous location --- at Volo.Abp.AspNetCore.Tracing.AbpCorrelationIdMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.AspNetCore.Localization.RequestLocalizationMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.RequestLocalization.AbpRequestLocalizationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context) 2022-05-18 16:34:08.424 +03:00 [INF] Request finished HTTP/1.1 POST https://localhost:44357/connect/token application/x-www-form-urlencoded 214 - 500 - text/plain;+charset=utf-8 2797.9186ms

May 23 '22 10:05 alexandis

You can try to change the environment(Database/Redis/WebServer) to troubleshoot the problem, as no one has reported such a problem.

May 24 '22 00:05 maliming

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

Jul 30 '22 17:07 stale[bot]