Thanks for the local Kubernetes test. Still I think a test via a deployed application to an Azure Kubernetes service would be a better comparison to our situation. One question still.... do you (Abp.io) have any production clients that are running abpFramework microservices template in an Azure Kubernetes Service? If so, can we find out what there metrics are for obtaining a token?
I will try deploy a ms template to the ASK cluster to reproduce the problem, could you share the full steps? thanks
I don't think it would do any good to try to give you our flavor of steps to build a AKS cluster and deploy a minimal AbpFramwork microservice solution. However, here is the Abp document to deploy to Kubernetes - https://abp.io/docs/8.3/solution-templates/microservice/helm-charts-and-kubernetes. Thanks for your help with this task.
We have deployed your authserver code to a second AKS cluster (our production cluster) and are getting the same slow response times in retrieving a token.
We have another app service running in the same AKS cluster that uses the Microsoft Identity libraries to obtain a JWT based token for other apis that are not part of the AbpFramework. This response time is sub 2 seconds.
Is there anyone on the support team that is a Kubernetes expert and can assist in tuning a kubernetes cluster? Do you have any clients running AbpFramework in an AKS environment that have better oauth - AuthServer - connect/token metrics?
So I've changed the config to debug globally in the AuthServer and ran 2 tests to get connect/tokens. The first test took 20 secs and the second test took 13 secs.
Lines where I see the big delays are as follows: 1st Test
| Line | TimeStamp | | | ---- | --------- | --- | | 647 | 15:44:24 | Start | | 763 | 15:44:25 | Dispose Connection | | 764 | 15:44:28 | OpenIddict.Server event | | 1084 | 15:44:31 | Dispose Connection | | 1085 | 15:44:33 | Try to use LDAP | | 2178 | 15:44:37 | Data reader 'Identity' is being disposed | | 2179 | 15:44:42 | Creating DbCommand for ExecuteReader | | 2804 | 15:44:45 | Finish |
2nd Test
| Line | TimeStamp | | | ---- | --------- | --- | | 3053 | 15:45:46 | Start | | 3141 | 15:45:46 | Dispose Connection | | 3142 | 15:45:50 | OpenIddict.Server event | | 3774 | 15:45:53 | Data reader 'Identity' is being disposed | | 3775 | 15:45:58 | Creating DbCommand for ExecuteReader | | 3797 | 15:45:59 | Executed DbCommand (807ms) | | 4292 | 15:44:59 | Finish |
I've sent the new log file via email. Thanks.
I sent you the file via email. Look at lines 7195 and 8548 for the 4 and 5 second delays.
I've added the suggested code to the AuthServer program.cs file and created a new image for the cpronabp-app-authserver container running in AKS.
I used Postman to call the 'oauth' connect/token endpoint with the credentials required to get a token. I've provided a snippet of the log and bolded the timestamps where I see excessive delays in the process. The total response time was 13.5 seconds. There are 2 spots where the logs have a 4 - 5 sec delay. This is 9 secs out of the 13 total to get a token.
Is there a setting that I can use to tell what is happening at these delay points? Also, I would like to share the full log with you for the connect/token POST so that you can see the full context but am not sure the protocol for sharing log files with the support team. We really need to figure out what is causing the delay of the connect/token process when running in AKS.
[16:28:44 INF] Request starting HTTP/1.1 POST http://authserver.cloverleafcms.dev/connect/token application/x-[www-form-urlencoded 512](http://www-form-urlencoded 512) [16:28:44 INF] The request URI matched a server endpoint: Token. [16:28:44 INF] The token request was successfully extracted: { "grant_type": "password", "username": "Fordz", "password": "[redacted]", "scope": "address email phone profile roles AccountService IdentityService AdministrationService SaasService ClientService ServicesService ClientServiceQueryService UserInfoQueryService DocumentService GuardianshipService NotesService ContactService EngagementLogService DocTemplateService FinancialsService RSSFeedService SmsService StaffService CommunicationsTemplateService MemberConfigService AIService CreditReportService DropdownCodeService HousingService", "client_id": "PublicAPI", "client_secret": "[redacted]" }. [16:28:44 DBG] Entity Framework Core 7.0.10 initialized 'IdentityServiceDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:7.0.10' with options: QuerySplittingBehavior=SplitQuery MigrationsHistoryTable=__IdentityService_Migrations [16:28:44 DBG] Compiling query expression: [removed] [16:28:44 DBG] Creating DbCommand for 'ExecuteReader'. [16:28:44 DBG] Creating DbConnection. [16:28:44 DBG] Created DbConnection. (0ms). [16:28:44 DBG] Created DbCommand for 'ExecuteReader' (0ms). [16:28:44 DBG] Initialized DbCommand for 'ExecuteReader' (0ms). [16:28:44 DBG] Opening connection to database 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:44 DBG] Opened connection to database 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:44 DBG] Executing DbCommand [removed] [16:28:44 INF] Executed DbCommand (5ms) [Parameters=[@__ef_filter__p_0='?' (DbType = Boolean)], CommandType='Text', CommandTimeout='30'] SELECT [o].[Id], [o].[ConcurrencyStamp], [o].[CreationTime], [o].[CreatorId], [o].[DeleterId], [o].[DeletionTime], [o].[Description], [o].[Descriptions], [o].[DisplayName], [o].[DisplayNames], [o].[ExtraProperties], [o].[IsDeleted], [o].[LastModificationTime], [o].[LastModifierId], [o].[Name], [o].[Properties], [o].[Resources] FROM [OpenIddictScopes] AS [o] WHERE (@__ef_filter__p_0 = CAST(1 AS bit) OR [o].[IsDeleted] = CAST(0 AS bit)) AND [o].[Name] IN (N'AccountService', N'IdentityService', N'AdministrationService', N'SaasService', N'ClientService', N'ServicesService', N'ClientServiceQueryService', N'UserInfoQueryService', N'DocumentService', N'GuardianshipService', N'NotesService', N'ContactService', N'EngagementLogService', N'DocTemplateService', N'FinancialsService', N'RSSFeedService', N'SmsService', N'StaffService', N'CommunicationsTemplateService', N'MemberConfigService', N'AIService', N'CreditReportService', N'DropdownCodeService', N'HousingService') [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:44 DBG] Closing data reader to 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:44 DBG] A data reader for 'CloverleafCMS_Identity' on server 'fincosql' is being disposed after spending 1ms reading results. [16:28:44 DBG] Closing connection to database 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:44 DBG] Closed connection to database 'CloverleafCMS_Identity' on server 'fincosql' (0ms). [16:28:44 DBG] DetectChanges starting for 'IdentityServiceDbContext'. [16:28:44 DBG] DetectChanges completed for 'IdentityServiceDbContext'. [16:28:44 DBG] DetectChanges starting for 'IdentityServiceDbContext'. [16:28:44 DBG] DetectChanges completed for 'IdentityServiceDbContext'. [16:28:44 DBG] SaveChanges starting for 'IdentityServiceDbContext'. [16:28:44 DBG] DetectChanges starting for 'IdentityServiceDbContext'. [16:28:44 DBG] DetectChanges completed for 'IdentityServiceDbContext'. [16:28:44 DBG] SaveChanges completed for 'IdentityServiceDbContext' with 0 entities written to the database. [16:28:44 DBG] 'IdentityServiceDbContext' disposed. [16:28:44 DBG] Disposing connection to database 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:44 DBG] Disposed connection to database '' on server '' (0ms). [16:28:48 DBG] Entity Framework Core 7.0.10 initialized 'IdentityServiceDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:7.0.10' with options: QuerySplittingBehavior=SplitQuery MigrationsHistoryTable=__IdentityService_Migrations [16:28:48 DBG] Compiling query expression: [removed] [16:28:48 DBG] Creating DbCommand for 'ExecuteReader'. [16:28:48 DBG] Creating DbConnection. [16:28:48 DBG] Created DbConnection. (0ms). [16:28:48 DBG] Created DbCommand for 'ExecuteReader' (0ms). [16:28:48 DBG] Initialized DbCommand for 'ExecuteReader' (0ms). [16:28:48 DBG] Opening connection to database 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:48 DBG] Opened connection to database 'CloverleafCMS_Identity' on server 'fincosql'. ... [16:28:52 DBG] Creating DbCommand for 'ExecuteReader'. [16:28:52 DBG] Created DbCommand for 'ExecuteReader' (0ms). [16:28:52 DBG] Initialized DbCommand for 'ExecuteReader' (0ms). [16:28:52 DBG] Executing DbCommand [Parameters=[@__ef_filter__p_0='?' (DbType = Boolean)], CommandType='Text', CommandTimeout='30'] SELECT [o].[Id], [o].[ConcurrencyStamp], [o].[CreationTime], [o].[CreatorId], [o].[DeleterId], [o].[DeletionTime], [o].[Description], [o].[Descriptions], [o].[DisplayName], [o].[DisplayNames], [o].[ExtraProperties], [o].[IsDeleted], [o].[LastModificationTime], [o].[LastModifierId], [o].[Name], [o].[Properties], [o].[Resources] FROM [OpenIddictScopes] AS [o] WHERE (@__ef_filter__p_0 = CAST(1 AS bit) OR [o].[IsDeleted] = CAST(0 AS bit)) AND [o].[Name] IN (N'address', N'email', N'phone', N'profile', N'roles', N'AccountService', N'IdentityService', N'AdministrationService', N'SaasService', N'ClientService', N'ServicesService', N'ClientServiceQueryService', N'UserInfoQueryService', N'DocumentService', N'GuardianshipService', N'NotesService', N'ContactService', N'EngagementLogService', N'DocTemplateService', N'FinancialsService', N'RSSFeedService', N'SmsService', N'StaffService', N'CommunicationsTemplateService', N'MemberConfigService', N'AIService', N'CreditReportService', N'DropdownCodeService', N'HousingService') [16:28:52 INF] Executed DbCommand (1ms) [Parameters=[@__ef_filter__p_0='?' (DbType = Boolean)], CommandType='Text', CommandTimeout='30'] SELECT [o].[Id], [o].[ConcurrencyStamp], [o].[CreationTime], [o].[CreatorId], [o].[DeleterId], [o].[DeletionTime], [o].[Description], [o].[Descriptions], [o].[DisplayName], [o].[DisplayNames], [o].[ExtraProperties], [o].[IsDeleted], [o].[LastModificationTime], [o].[LastModifierId], [o].[Name], [o].[Properties], [o].[Resources] FROM [OpenIddictScopes] AS [o] WHERE (@__ef_filter__p_0 = CAST(1 AS bit) OR [o].[IsDeleted] = CAST(0 AS bit)) AND [o].[Name] IN (N'address', N'email', N'phone', N'profile', N'roles', N'AccountService', N'IdentityService', N'AdministrationService', N'SaasService', N'ClientService', N'ServicesService', N'ClientServiceQueryService', N'UserInfoQueryService', N'DocumentService', N'GuardianshipService', N'NotesService', N'ContactService', N'EngagementLogService', N'DocTemplateService', N'FinancialsService', N'RSSFeedService', N'SmsService', N'StaffService', N'CommunicationsTemplateService', N'MemberConfigService', N'AIService', N'CreditReportService', N'DropdownCodeService', N'HousingService') [16:28:52 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. [16:28:52 DBG] Context 'IdentityServiceDbContext' started tracking 'OpenIddictScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values. ... [16:28:52 DBG] Closing data reader to 'CloverleafCMS_Identity' on server 'fincosql'. [16:28:52 DBG] A data reader for 'CloverleafCMS_Identity' on server 'fincosql' is being disposed after spending 1ms reading results. [16:28:57 DBG] Creating DbCommand for 'ExecuteReader'. [16:28:57 DBG] Created DbCommand for 'ExecuteReader' (0ms). ... [16:28:58 INF] Request finished HTTP/1.1 POST http://authserver.cloverleafcms.dev/connect/token application/x-[www-form-urlencoded 512](http://www-form-urlencoded 512) - 200 2512 application/json;charset=UTF-8 13498.6988ms
Hi, sorry for the delay in response... we had a 'national holiday' in the States yesterday.
I need a little more direction on what you are suggesting I try. Are you showing an image of the Volo.Abp.Caching.StackExchangeRedis project? Or is it of the 'ProjectName\Shared\Hosting\Microservices project? What project/module class do I apply this debug logging statement?
My AKS Redis service is a container of the Redis/Alpine image. I don't believe you are asking to add logging to it.
Hi,
may I ask is the Redis Server available?
Yes... it is running on AKS? Is there anything in particular regarding the Redis Server that I need to be looking for?
Changed the log levels to the following on the AuthServer app running in Azure Kubernetes Service. The POST to get a token took 10 seconds. The slow processes seem to be 'validating scopes' and 'writing audit logs'. Please investigate and let us know how we can speed this up.
"Logging": { "LogLevel": { "Default": "Debug", "Microsoft": "Debug", "Microsoft.Hosting.Lifetime": "Debug", "CprOnAbp.AuthServer": "Debug", "Microsoft.EntityFrameworkCore": "Debug" } },
[16:18:39 INF] Request starting HTTP/1.1 POST http://authserver.cloverleafcms.dev/connect/token application/x-www-form-urlencoded 477 ... [16:18:39 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateProofKeyForCodeExchangeParameters. [16:18:42 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateScopes. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateClientId. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateClientType. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateClientSecret. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateEndpointPermissions. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateGrantTypePermissions. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateScopePermissions. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateProofKeyForCodeExchangeRequirement. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateToken. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidatePresenters. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateRedirectUri. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateCodeVerifier. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateGrantedScopes. [16:18:43 INF] The token request was successfully validated. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateTokenRequest. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+HandleTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+AttachPrincipal. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+HandleTokenRequestContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+EnablePassthroughMode 2[[OpenIddict.Server.OpenIddictServerEvents+HandleTokenRequestContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f],[OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlerFilters+RequireTokenEndpointPassthroughEnabled, OpenIddict.Server.AspNetCore, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+HandleTokenRequestContext was marked as skipped by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+EnablePassthroughMode 2[[OpenIddict.Server.OpenIddictServerEvents+HandleTokenRequestContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f],[OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlerFilters+RequireTokenEndpointPassthroughEnabled, OpenIddict.Server.AspNetCore, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+HandleTokenRequest. [16:18:43 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was marked as skipped by OpenIddict.Server.OpenIddictServerHandlers+Exchange+HandleTokenRequest. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.AspNetCore.OpenIddictValidationAspNetCoreHandlers+ValidateHostHeader. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.OpenIddictValidationHandlers+ResolveServerConfiguration. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.OpenIddictValidationHandlers+EvaluateValidatedTokens. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.AspNetCore.OpenIddictValidationAspNetCoreHandlers+ExtractAccessTokenFromAuthorizationHeader. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.AspNetCore.OpenIddictValidationAspNetCoreHandlers+ExtractAccessTokenFromBodyForm. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.AspNetCore.OpenIddictValidationAspNetCoreHandlers+ExtractAccessTokenFromQueryString. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was successfully processed by OpenIddict.Validation.OpenIddictValidationHandlers+ValidateRequiredTokens. [16:18:43 DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessAuthenticationContext was marked as rejected by OpenIddict.Validation.OpenIddictValidationHandlers+ValidateRequiredTokens. [16:18:43 DBG] AuthenticationScheme: OpenIddict.Validation.AspNetCore was not authenticated. [16:18:44 INF] Executing endpoint 'Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)' [16:18:44 INF] Route matched with {action = "Handle", controller = "Token", area = "", page = ""}. Executing controller action with signature System.Threading.Tasks.Task 1[Microsoft.AspNetCore.Mvc.IActionResult] HandleAsync() on controller Volo.Abp.OpenIddict.Controllers.TokenController (Volo.Abp.OpenIddict.AspNetCore). [16:18:44 INF] Skipping the execution of current filter as its not the most effective filter implementing the policy Microsoft.AspNetCore.Mvc.ViewFeatures.IAntiforgeryPolicy [16:18:44 INF] Try to use LDAP for external authentication [16:18:44 WRN] Ldap login feature is not enabled! [16:18:44 INF] Try to use OAUTH for external authentication [16:18:44 WRN] OAuth login feature is not enabled! [16:18:46 DBG] Added 0 entity changes to the current audit log [16:18:46 DBG] Added 0 entity changes to the current audit log [16:18:46 DBG] Added 0 entity changes to the current audit log [16:18:46 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 INF] Executing SignInResult with authentication scheme (OpenIddict.Server.AspNetCore) and the following principal: System.Security.Claims.ClaimsPrincipal. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+ResolveHostSignInProperties. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+ValidateSignInDemand. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+RedeemTokenEntry. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+RestoreInternalClaims. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+AttachHostProperties. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+AttachDefaultScopes. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+AttachDefaultPresenters. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+InferResources. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+EvaluateGeneratedTokens. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+AttachAuthorization. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by Volo.Abp.OpenIddict.RemoveClaimsFromClientCredentialsGrantType. [16:18:49 DBG] 'AspNet.Identity.SecurityStamp' was excluded from the access token claims. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+PrepareAccessTokenPrincipal. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+GenerateTokenContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Protection+AttachSecurityCredentials. [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+GenerateTokenContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Protection+CreateTokenEntry. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+GenerateTokenContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Protection+GenerateIdentityModelToken. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+GenerateTokenContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Protection+BeautifyToken. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+GenerateAccessToken. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+AttachCustomSignInParameters. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+AttachSignInParameters. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+NormalizeErrorResponse. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+AttachHttpResponseCode 1[[OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+AttachCacheControlHeader 1[[OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+AttachWwwAuthenticateHeader 1[[OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was successfully processed by Volo.Abp.Account.Web.ExtensionGrants.LinkLoginExtensionGrantProcessJsonResponse. [16:18:49 INF] The response was successfully returned as a JSON document: { "access_token": "[redacted]", "token_type": "Bearer", "expires_in": 3599 }. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+ProcessJsonResponse 1[[OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext was marked as handled by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+ProcessJsonResponse 1[[OpenIddict.Server.OpenIddictServerEvents+ApplyTokenResponseContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ApplyTokenResponse 1[[OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext was marked as handled by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ApplyTokenResponse`1[[OpenIddict.Server.OpenIddictServerEvents+ProcessSignInContext, OpenIddict.Server, Version=4.2.0.0, Culture=neutral, PublicKeyToken=35a561290d20de2f]]. [16:18:49 INF] Executed action Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore) in 5416.1013ms [16:18:49 INF] Executed endpoint 'Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)' [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 DBG] Added 0 entity changes to the current audit log [16:18:49 INF] Request finished HTTP/1.1 POST http://authserver.cloverleafcms.dev/connect/token application/x-www-form-urlencoded 477 - 200 2413 application/json;charset=UTF-8 9941.4948ms
We are experiencing the same delay going thru the AuthServer app login screen. Please investigate and let us know what we can do to speed things up.
I've set the logging attributes to the following in the AuthServer. "Logging": { "LogLevel": { "Default": "Information", "Microsoft": "Warning", "Microsoft.Hosting.Lifetime": "Information", "CprOnAbp.AuthServer": "Trace" } },
In my initial comparison of the log files for the POST localhost and POST AKS, I can see that the following lines indicate where slowness has occurred.
[14:40:29 INF] Request starting HTTP/1.1 POST http://authserver.cloverleafcms.dev/connect/token application/x-[[www-form-urlencoded 478](http://www-form-urlencoded](http://www-form-urlencoded 478](http://www-form-urlencoded) 478) ... [14:40:29 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateProofKeyForCodeExchangeParameters. [14:40:33 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateScopes. ... [14:40:34 INF] Try to use LDAP for external authentication [14:40:35 WRN] Ldap login feature is not enabled! [14:40:35 INF] Try to use OAUTH for external authentication [14:40:35 WRN] OAuth login feature is not enabled! [14:40:37 DBG] Added 0 entity changes to the current audit log [14:40:37 DBG] Added 0 entity changes to the current audit log [14:40:40 DBG] Added 0 entity changes to the current audit log [14:40:40 DBG] Added 0 entity changes to the current audit log [14:40:40 DBG] Added 0 entity changes to the current audit log [14:40:40 DBG] Added 0 entity changes to the current audit log ... [14:40:40 INF] Executed action Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore) in 6301.6679ms [14:40:40 INF] Executed endpoint 'Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)' [14:40:40 DBG] Added 0 entity changes to the current audit log [14:40:40 DBG] Added 0 entity changes to the current audit log [14:40:41 DBG] Added 0 entity changes to the current audit log [14:40:41 DBG] Added 0 entity changes to the current audit log [14:40:41 INF] Request finished HTTP/1.1 POST http://authserver.cloverleafcms.dev/connect/token application/x-[[www-form-urlencoded 478](http://www-form-urlencoded](http://www-form-urlencoded 478](http://www-form-urlencoded) 478) - 200 2417 application/json;charset=UTF-8 12554.8431ms
From Localhost log [09:09:17 INF] Request starting HTTP/1.1 POST https://localhost:44322/connect/token application/x-[www-form-urlencoded 477](http://www-form-urlencoded 477) ... [09:09:17 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateProofKeyForCodeExchangeParameters. [09:09:17 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateScopeParameter. [09:09:18 DBG] The event OpenIddict.Server.OpenIddictServerEvents+ValidateTokenRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+Exchange+ValidateScopes. ... [09:09:18 INF] Try to use LDAP for external authentication [09:09:18 WRN] Ldap login feature is not enabled! [09:09:18 INF] Try to use OAUTH for external authentication [09:09:18 WRN] OAuth login feature is not enabled! [09:09:19 DBG] Added 0 entity changes to the current audit log [09:09:19 DBG] Added 0 entity changes to the current audit log [09:09:19 DBG] Added 0 entity changes to the current audit log ... [09:09:19 INF] Executed action Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore) in 1354.6533ms [09:09:19 INF] Executed endpoint 'Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)' [09:09:19 DBG] Added 0 entity changes to the current audit log [09:09:19 DBG] Added 0 entity changes to the current audit log [09:09:20 DBG] Added 0 entity changes to the current audit log [09:09:20 DBG] Added 0 entity changes to the current audit log [09:09:20 INF] Request finished HTTP/1.1 POST https://localhost:44322/connect/token application/x-[www-form-urlencoded 477](http://www-form-urlencoded 477) - 200 2400 application/json;charset=UTF-8 2147.3657ms
