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
hi,
So I was able to get to your suggestions in ticket #6452 and ran into an issue with overriding the connect/token endpoint of the TokenController to output a log to show the tenant.
To recap... the initial issue we are trying to solve is: "We're using the microservice template and using the auth-server app for authentication. The auth-server application has been slightly modified for custom branding. We have a .net API to get a token using the IdentityModel.Client. When I call the API using Postman that's pointing to the auth-server running on localhost via Tye I'm able to successfully get a token. When I call the API pointing to the auth-server running in Azure Kubernetes I get an invalid username and password error. The code is the exact same. The database is the same and the credentials are the exact same."
I'm getting a duplicate route error and am not quite sure how to get around it 'to override the HandlePasswordAysnc method of TokenController' as suggested to inspect the Tenant.Name. I cannot change the route of 'connect/token' as it is set by OAuth.
MyTokenController in AuthServer
using System; using System.Threading.Tasks; using Microsoft.AspNetCore.Mvc; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Options; using OpenIddict.Abstractions; using Volo.Abp.OpenIddict.Controllers; using Volo.Abp.OpenIddict.ExtensionGrantTypes;
namespace CprOnAbp.AuthServer{ [Route("connect/token")] [IgnoreAntiforgeryToken] public class MyTokenController : TokenController {
public MyTokenController()
{
}
[HttpGet, HttpPost, Produces("application/json")]
public override async Task<IActionResult> HandleAsync()
{
var request = await GetOpenIddictServerRequestAsync(HttpContext);
if (request.IsPasswordGrantType())
{
var tenant = await TenantConfigurationProvider.GetAsync(saveResolveResult: false);
Console.WriteLine($"Tenant Name: {tenant.Name}");
// Call the base implementation if needed
return await base.HandlePasswordAsync(request);
//return await HandlePasswordAsync(request); // Call the overridden HandlePasswordAsync method
}
// Add other grant type handling here as needed
return await base.HandleAsync();
}
// Override the HandlePasswordAsync method
//protected override async Task<IActionResult> HandlePasswordAsync(OpenIddictRequest request)
//{
// // Your custom implementation goes here
// var tenant = await TenantConfigurationProvider.GetAsync(saveResolveResult: false);
// Console.WriteLine($"Tenant Name: {tenant.Name}");
// // Call the base implementation if needed
// return await base.HandlePasswordAsync(request);
//}
}
}
Here is the returned error.
[12:06:20 ERR] An unhandled exception has occurred while executing the request. Microsoft.AspNetCore.Routing.Matching.AmbiguousMatchException: The request matched multiple endpoints. Matches: CprOnAbp.AuthServer.MyTokenController.HandleAsync (CprOnAbp.AuthServer) Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore) at Microsoft.AspNetCore.Routing.Matching.DefaultEndpointSelector.ReportAmbiguity(CandidateState[] candidateState) at Microsoft.AspNetCore.Routing.Matching.DefaultEndpointSelector.ProcessFinalCandidates(HttpContext httpContext, CandidateState[] candidateState) at Microsoft.AspNetCore.Routing.Matching.DfaMatcher.MatchAsync(HttpContext httpContext) at Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.Invoke(HttpContext httpContext) at Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware.Invoke(HttpContext context) at Volo.Abp.AspNetCore.Security.AbpSecurityHeadersMiddleware.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.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.DeveloperExceptionPageMiddlewareImpl.Invoke(HttpContext context) [12:06:20 INF] Request finished HTTP/1.1 POST https://localhost:44322/connect/token application/x-[[[[www-form-urlencoded 387](http://www-form-urlencoded](http://www-form-urlencoded](http://www-form-urlencoded](http://www-form-urlencoded 387](http://www-form-urlencoded](http://www-form-urlencoded](http://www-form-urlencoded) 387](http://www-form-urlencoded](http://www-form-urlencoded](http://www-form-urlencoded)) 387](http://www-form-urlencoded) 387) - 500 - text/plain;+charset=utf-8 251.5204ms
I've shared our 2 projects that are needed to recreate this issue with Maliming. Auth-Server and oauth-api
Thanks for your help.