Response time for obtaining a token from the AuthServer running in K8s cluster is excessive. #7785

19 Answer(s)

• 

  0

  liangshiwei created 3 months ago

  Support Team Fullstack Developer

  Hi,

  you can set all log levels to debug(including EF Core), This way we can further narrow down the problem area

  Save Cancel
• 

  0

  fordz created 2 months ago

  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

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  Hi,

  may I ask is the Redis Server available?

  Save Cancel
• 

  0

  fordz created 2 months ago

  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?

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  can you change ef core level to debug?

  Save Cancel
• 

  0

  fordz created 2 months ago

  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.

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  Hi,

  i mean change the AuthServer logger level

  Save Cancel
• 

  0

  fordz created 2 months ago

  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

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  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.

  okay, you can email me.

  shiwei.liang@volosoft.com

  Save Cancel
• 

  0

  fordz created 2 months ago

  I sent you the file via email. Look at lines 7195 and 8548 for the 4 and 5 second delays.

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  Hi,

  Sorry again.

  According to the logs, it seems that nothing happened and just waited for 4-5 seconds and there is no log about openiddict.

  Can you set the log level to debug globally?

  configuration.MinimumLevel.Debug()

  Save Cancel
• 

  0

  fordz created 2 months ago

  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.

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  Hi,

  After checking, this does not seem to be a problem with code. It's looks like a problem with the Environment(database, server). you can try deploying it in other environments to check whether it is an environment problem.

  Save Cancel
• 

  0

  fordz created 2 months ago

  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?

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  I will try deploy a ms template to the ASK cluster to reproduce the problem, could you share the full steps? thanks

  Save Cancel
• 

  0

  fordz created 2 months ago

  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.

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  HI,

  i could not reproduce the problem.

  Since I don't have an azure subscription I use a local k8s environment

  My steps

  Create a new ms template

  • abp new Qa7785 -t microservice-pro -v 7.2.2 --old Deploy the project according to the README.md under k8s

  

  2024-09-12 17:09:45 [09:09:45 INF] Request starting HTTP/1.1 POST http://qa7785-st-authserver/Account/Login?ReturnUrl=%2Fconnect%2Fauthorize%3Fclient_id%3DWeb%26redirect_uri%3Dhttps%253A%252F%252Fqa7785-st-web%252Fsignin-oidc%26response_type%3Dcode%2520id_token%26scope%3Dopenid%2520profile%2520roles%2520email%2520phone%2520AccountService%2520IdentityService%2520AdministrationService%2520SaasService%2520ProductService%26response_mode%3Dform_post%26nonce%3D638617289811389097.MjhmZjk3MTYtN2EyOS00N2U1LWFiOGYtODhkNGMwODUxYmZjMjNiYzM1ZTQtNTM5Yi00MmY1LWFjYjUtZDM2NjZhZmRhYjM3%26state%3DCfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf%26x-client-SKU%3DID_NET6_0%26x-client-ver%3D6.15.1.0 application/x-www-form-urlencoded 291
  2024-09-12 17:09:45 [09:09:45 INF] CORS policy execution failed.
  2024-09-12 17:09:45 [09:09:45 INF] Request origin https://qa7785-st-authserver does not have permission to access the resource.
  2024-09-12 17:09:45 [09:09:45 INF] Executing endpoint '/Account/Login'
  2024-09-12 17:09:45 [09:09:45 INF] Route matched with {page = "/Account/Login", area = "", action = "", controller = ""}. Executing page /Account/Login
  2024-09-12 17:09:45 [09:09:45 INF] Skipping the execution of current filter as its not the most effective filter implementing the policy Microsoft.AspNetCore.Mvc.ViewFeatures.IAntiforgeryPolicy
  2024-09-12 17:09:45 [09:09:45 INF] Executing handler method Volo.Abp.Account.Public.Web.Pages.Account.LoginModel.OnPostAsync - ModelState is Valid
  2024-09-12 17:09:45 [09:09:45 INF] Try to use LDAP for external authentication
  2024-09-12 17:09:45 [09:09:45 WRN] Ldap login feature is not enabled!
  2024-09-12 17:09:45 [09:09:45 INF] Try to use OAUTH for external authentication
  2024-09-12 17:09:45 [09:09:45 WRN] OAuth login feature is not enabled!
  2024-09-12 17:09:45 [09:09:45 INF] AuthenticationScheme: Identity.Application signed in.
  2024-09-12 17:09:45 [09:09:45 INF] Executed handler method OnPostAsync, returned result Microsoft.AspNetCore.Mvc.RedirectResult.
  2024-09-12 17:09:45 [09:09:45 INF] Executing RedirectResult, redirecting to /connect/authorize?client_id=Web&redirect_uri=https%3A%2F%2Fqa7785-st-web%2Fsignin-oidc&response_type=code%20id_token&scope=openid%20profile%20roles%20email%20phone%20AccountService%20IdentityService%20AdministrationService%20SaasService%20ProductService&response_mode=form_post&nonce=638617289811389097.MjhmZjk3MTYtN2EyOS00N2U1LWFiOGYtODhkNGMwODUxYmZjMjNiYzM1ZTQtNTM5Yi00MmY1LWFjYjUtZDM2NjZhZmRhYjM3&state=CfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf&x-client-SKU=ID_NET6_0&x-client-ver=6.15.1.0.
  2024-09-12 17:09:45 [09:09:45 INF] Executed page /Account/Login in 226.1494ms
  2024-09-12 17:09:45 [09:09:45 INF] Executed endpoint '/Account/Login'
  2024-09-12 17:09:45 [09:09:45 INF] Request finished HTTP/1.1 POST http://qa7785-st-authserver/Account/Login?ReturnUrl=%2Fconnect%2Fauthorize%3Fclient_id%3DWeb%26redirect_uri%3Dhttps%253A%252F%252Fqa7785-st-web%252Fsignin-oidc%26response_type%3Dcode%2520id_token%26scope%3Dopenid%2520profile%2520roles%2520email%2520phone%2520AccountService%2520IdentityService%2520AdministrationService%2520SaasService%2520ProductService%26response_mode%3Dform_post%26nonce%3D638617289811389097.MjhmZjk3MTYtN2EyOS00N2U1LWFiOGYtODhkNGMwODUxYmZjMjNiYzM1ZTQtNTM5Yi00MmY1LWFjYjUtZDM2NjZhZmRhYjM3%26state%3DCfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf%26x-client-SKU%3DID_NET6_0%26x-client-ver%3D6.15.1.0 application/x-www-form-urlencoded 291 - 302 0 - 292.3347ms
  2024-09-12 17:09:45 [09:09:45 INF] Request starting HTTP/1.1 GET http://qa7785-st-authserver/connect/authorize?client_id=Web&redirect_uri=https%3A%2F%2Fqa7785-st-web%2Fsignin-oidc&response_type=code%20id_token&scope=openid%20profile%20roles%20email%20phone%20AccountService%20IdentityService%20AdministrationService%20SaasService%20ProductService&response_mode=form_post&nonce=638617289811389097.MjhmZjk3MTYtN2EyOS00N2U1LWFiOGYtODhkNGMwODUxYmZjMjNiYzM1ZTQtNTM5Yi00MmY1LWFjYjUtZDM2NjZhZmRhYjM3&state=CfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf&x-client-SKU=ID_NET6_0&x-client-ver=6.15.1.0 - -
  2024-09-12 17:09:45 [09:09:45 INF] The request URI matched a server endpoint: Authorization.
  2024-09-12 17:09:45 [09:09:45 INF] The authorization request was successfully extracted: {
  2024-09-12 17:09:45   "client_id": "Web",
  2024-09-12 17:09:45   "redirect_uri": "https://qa7785-st-web/signin-oidc",
  2024-09-12 17:09:45   "response_type": "code id_token",
  2024-09-12 17:09:45   "scope": "openid profile roles email phone AccountService IdentityService AdministrationService SaasService ProductService",
  2024-09-12 17:09:45   "response_mode": "form_post",
  2024-09-12 17:09:45   "nonce": "638617289811389097.MjhmZjk3MTYtN2EyOS00N2U1LWFiOGYtODhkNGMwODUxYmZjMjNiYzM1ZTQtNTM5Yi00MmY1LWFjYjUtZDM2NjZhZmRhYjM3",
  2024-09-12 17:09:45   "state": "CfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf",
  2024-09-12 17:09:45   "x-client-SKU": "ID_NET6_0",
  2024-09-12 17:09:45   "x-client-ver": "6.15.1.0"
  2024-09-12 17:09:45 }.
  2024-09-12 17:09:45 [09:09:45 INF] The authorization request was successfully validated.
  2024-09-12 17:09:45 [09:09:45 INF] Executing endpoint 'Volo.Abp.OpenIddict.Controllers.AuthorizeController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)'
  2024-09-12 17:09:45 [09:09:45 INF] Route matched with {action = "Handle", controller = "Authorize", area = "", page = ""}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] HandleAsync() on controller Volo.Abp.OpenIddict.Controllers.AuthorizeController (Volo.Abp.OpenIddict.AspNetCore).
  2024-09-12 17:09:45 [09:09:45 INF] Skipping the execution of current filter as its not the most effective filter implementing the policy Microsoft.AspNetCore.Mvc.ViewFeatures.IAntiforgeryPolicy
  2024-09-12 17:09:45 [09:09:45 INF] Executing SignInResult with authentication scheme (OpenIddict.Server.AspNetCore) and the following principal: System.Security.Claims.ClaimsPrincipal.
  2024-09-12 17:09:45 [09:09:45 INF] The authorization response was successfully returned to 'https://qa7785-st-web/signin-oidc' using the form post response mode: {
  2024-09-12 17:09:45   "code": "[redacted]",
  2024-09-12 17:09:45   "id_token": "[redacted]",
  2024-09-12 17:09:45   "state": "CfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf",
  2024-09-12 17:09:45   "iss": "http://qa7785-st-authserver/"
  2024-09-12 17:09:45 }.
  2024-09-12 17:09:45 [09:09:45 INF] Executed action Volo.Abp.OpenIddict.Controllers.AuthorizeController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore) in 161.4656ms
  2024-09-12 17:09:45 [09:09:45 INF] Executed endpoint 'Volo.Abp.OpenIddict.Controllers.AuthorizeController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)'
  2024-09-12 17:09:45 [09:09:45 INF] Request finished HTTP/1.1 GET http://qa7785-st-authserver/connect/authorize?client_id=Web&redirect_uri=https%3A%2F%2Fqa7785-st-web%2Fsignin-oidc&response_type=code%20id_token&scope=openid%20profile%20roles%20email%20phone%20AccountService%20IdentityService%20AdministrationService%20SaasService%20ProductService&response_mode=form_post&nonce=638617289811389097.MjhmZjk3MTYtN2EyOS00N2U1LWFiOGYtODhkNGMwODUxYmZjMjNiYzM1ZTQtNTM5Yi00MmY1LWFjYjUtZDM2NjZhZmRhYjM3&state=CfDJ8IEEMWWN7RFAlJWhi5LTjUOus_I6dy7aKa8OWYlv0_y0DM7cVFW90ndOAR2uSrJ53XAsZrXR0edhBqEcu5QJHz4_3somqIxc9Oo1AgC_IKKMr8TFvmzCm1_gDA-pw778cTth5lE0upTO8BakV9gbi8SbxJHOTHrlcxiYylDJK0X8OLqgRCZQYncU4ncZlvD_NupH4fvEe-2gvwE50KFQ5CtrnVPaxd1NfnffJid7twGQksEUKaxxj6nvfwtkouhm86MD6mARo_1O4Tq4PYA4DtzVPlfI4BAf-iPZ3sHbYYZf&x-client-SKU=ID_NET6_0&x-client-ver=6.15.1.0 - - - 200 1972 text/html;charset=UTF-8 184.2490ms
  2024-09-12 17:09:45 [09:09:45 INF] Request starting HTTP/1.1 POST http://qa7785-st-authserver/connect/token application/x-www-form-urlencoded 171
  2024-09-12 17:09:45 [09:09:45 INF] The request URI matched a server endpoint: Token.
  2024-09-12 17:09:45 [09:09:45 INF] The token request was successfully extracted: {
  2024-09-12 17:09:45   "client_id": "Web",
  2024-09-12 17:09:45   "client_secret": "[redacted]",
  2024-09-12 17:09:45   "code": "[redacted]",
  2024-09-12 17:09:45   "grant_type": "authorization_code",
  2024-09-12 17:09:45   "redirect_uri": "https://qa7785-st-web/signin-oidc"
  2024-09-12 17:09:45 }.
  2024-09-12 17:09:45 [09:09:45 INF] The token request was successfully validated.
  2024-09-12 17:09:45 [09:09:45 INF] Executing endpoint 'Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)'
  2024-09-12 17:09:45 [09:09:45 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).
  2024-09-12 17:09:45 [09:09:45 INF] Skipping the execution of current filter as its not the most effective filter implementing the policy Microsoft.AspNetCore.Mvc.ViewFeatures.IAntiforgeryPolicy
  2024-09-12 17:09:45 [09:09:45 INF] Executing SignInResult with authentication scheme (OpenIddict.Server.AspNetCore) and the following principal: System.Security.Claims.ClaimsPrincipal.
  2024-09-12 17:09:46 [09:09:46 INF] The token '5b15b949-96df-0dbb-9821-3a14f7abc213' was successfully marked as redeemed.
  2024-09-12 17:09:46 [09:09:46 INF] The response was successfully returned as a JSON document: {
  2024-09-12 17:09:46   "access_token": "[redacted]",
  2024-09-12 17:09:46   "token_type": "Bearer",
  2024-09-12 17:09:46   "expires_in": 3600,
  2024-09-12 17:09:46   "scope": "openid profile roles email phone AccountService IdentityService AdministrationService SaasService ProductService",
  2024-09-12 17:09:46   "id_token": "[redacted]"
  2024-09-12 17:09:46 }.
  2024-09-12 17:09:46 [09:09:46 INF] Executed action Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore) in 209.0545ms
  2024-09-12 17:09:46 [09:09:46 INF] Executed endpoint 'Volo.Abp.OpenIddict.Controllers.TokenController.HandleAsync (Volo.Abp.OpenIddict.AspNetCore)'
  2024-09-12 17:09:46 [09:09:46 INF] Request finished HTTP/1.1 POST http://qa7785-st-authserver/connect/token application/x-www-form-urlencoded 171 - 200 2779 application/json;charset=UTF-8 264.7367ms
  

  Save Cancel
• 

  0

  fordz created 2 months ago

  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?

  Save Cancel
• 

  0

  liangshiwei created 2 months ago

  Support Team Fullstack Developer

  Hi,

  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

  Yes, but I don't have an Azure subscription

  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 think so, you can ask it in the ABP's discord channel.

  Save Cancel