Skip to content
This repository was archived by the owner on Mar 6, 2025. It is now read-only.

End less loop on InteractionService.GetAuthorizationContextAsync call #4386

Closed
jmatheti opened this issue May 11, 2020 · 7 comments
Closed

End less loop on InteractionService.GetAuthorizationContextAsync call #4386

jmatheti opened this issue May 11, 2020 · 7 comments
Assignees
@brockallen
Labels
bug report question

Comments

@jmatheti
Copy link

The issue exists with Identity Server 3.1.1 - .Net core 3.1
but not with the Identity server 2.3.4 - .Net core 2.1.

The issue causing the stack overflow exception and causing the w3wp.exe crash eventually application going down.

The issue has been reported in the aspnetcore repo first and identified the call stack, after the modifications by removing the call to interactionService.GetAuthorizationContextAsync the new build is not producing the issue, hence its here.

the issue can not produced consistently in all environments, some of our environments such as development are working without any issues but the same is failing in our other all environments. Some environments the issue can be produces with a simple multiple logins using a multiple clients but in other environments ZAP scan is reproducing.

Design/ implementation

AccountsViewModel fluent validation constructor calling the interactionService.GetAuthorizationContextAsync passing the returnUrl to find out the ClientId to apply the relevant customization to the login page GET

Issue / Steps to reproduce the problem

Using the OWASP ZAP scan - attack mode insane strength.

some of our environments -

Identity server with an angular client and MVC client can also be produced with a simple browsing of the sites.

Login using the angular app.
Initialize the login to MVC application, which SSO will kicks in and then the application is crashing.

Relevant parts of the log file

See the dump call stack in here 

2020-05-08 14:17:43.593 +12:00 [INF] Request starting HTTP/2.0 GET https:///connect/authorize?client_id=core&redirect_uri=https%3A%2F%2Flogin.aspx&response_mode=form_post&response_type=code%20id_token%20token&scope=openid%20profile%20api.internal%20legacy%20offline_access&state=OpenIdConnect.AuthenticationProperties%3DTNEHTuVJsCX1oBNmxfetk5diX64PCIyKJEMlZ8hO9pfKRWrb5icykd6ix55dc36wWxwL_z1yaMBu56upc-jVC6khQkVewjTMvsyqXsZ_sNimMoN8Ou4E7R_Pra2Px2TohCU0VJrNIQLQ5oLxqf3-mbPXyOS1fyix7bmsTM_I3bJgzTiYK0IMKxHYBWHodPLTVugezTqzXAHNFotYg_ChaLWLBFIIfDXjCSanYcuD2powIsldhO0xSt_Kehl7CdufqQXuY-JXXJgS0FOt_y71S1EcNh3cpNX1AySG-zoyPNln5L98IwHWMbeMlQKrOz99OcuoN3-UvH-IoFpsF--clCIvdP0BqqJXz7zKPsVKqOu8hvEjeeTHrtAOsFva3ovRM_M68uFi4YyGJpC-xBro5f3JeUPfigaYDwx3fHkMTEM&nonce=637245010635444378.YmJmMzQ0ZDctY2M4ZS00MmE3LWI1NjktOTM2ZDc5ZDEzOTI3NmFmNzIwYjYtZWI2Yy00Mjc4LWFlMTYtMzBmODliYTBlOGI0&x-client-SKU=ID_NET451&x-client-ver=5.2.1.0  
2020-05-08 14:17:43.593 +12:00 [VRB] All hosts are allowed.
2020-05-08 14:17:43.593 +12:00 [VRB] Adding HSTS header to response.
2020-05-08 14:17:43.593 +12:00 [VRB] Adding HSTS header to response.
2020-05-08 14:17:43.593 +12:00 [DBG] The request path /connect/authorize does not match a supported file type
2020-05-08 14:17:43.593 +12:00 [DBG] No candidates found for the request path '/connect/authorize'
2020-05-08 14:17:43.593 +12:00 [DBG] Request did not match any endpoints
2020-05-08 14:17:43.594 +12:00 [VRB] Performing unprotect operation to key {590c83d6-1e15-4bfc-aadf-d9a48b674461} with purposes ('IdentityManagementService', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').
2020-05-08 14:17:43.595 +12:00 [VRB] returnUrl is not valid
2020-05-08 14:17:43.595 +12:00 [VRB] No AuthorizationRequest being returned
2020-05-08 14:17:43.595 +12:00 [VRB] No AuthorizationRequest being returned
2020-05-08 14:17:43.596 +12:00 [INF] Entity Framework Core 3.1.1 initialized 'ApplicationDbContext' using provider 'Devart.Data.Oracle.Entity.EFCore' with options: MigrationsAssembly=AC.Auth.Server.Entities MigrationsHistoryTable=__EFMigrationsHistory 
2020-05-08 14:17:43.598 +12:00 [DBG] AuthenticationScheme: Identity.Application was successfully authenticated.
2020-05-08 14:17:43.598 +12:00 [DBG] AuthenticationScheme: Identity.Application was successfully authenticated.
2020-05-08 14:17:43.598 +12:00 [DBG] Request path /connect/authorize matched to endpoint type Authorize
2020-05-08 14:17:43.604 +12:00 [DBG] Endpoint enabled: Authorize, successfully created handler: IdentityServer4.Endpoints.AuthorizeEndpoint
2020-05-08 14:17:43.604 +12:00 [INF] Invoking IdentityServer endpoint: IdentityServer4.Endpoints.AuthorizeEndpoint for /connect/authorize
2020-05-08 14:17:43.604 +12:00 [DBG] Start authorize request
2020-05-08 14:17:43.604 +12:00 [DBG] User in authorize request: 100000497
2020-05-08 14:17:43.604 +12:00 [DBG] Start authorize request protocol validation
2020-05-08 14:17:43.605 +12:00 [VRB] Cache miss for emt.core
2020-05-08 14:17:43.605 +12:00 [INF] Entity Framework Core 3.1.1 initialized 'OAuthConfigDbContext' using provider 'Devart.Data.Oracle.Entity.EFCore' with options: MigrationsAssembly=AC.Auth.Server.Entities MigrationsHistoryTable=__EFMigrationsHistory 
2020-05-08 14:17:43.606 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.607 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.607 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.607 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.607 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT t.Id, t.AbsoluteRefreshTokenLifetime, t.AccessTokenLifetime, t.AccessTokenType, t.AllowAccessTokensViaBrowser, t.AllowOfflineAccess, t.AllowPlainTextPkce, t.AllowRememberConsent, t.AlwaysIncUserClaimsInIdToken, t.AlwaysSendClientClaims, t.AuthorizationCodeLifetime, t.BackChannelLogoutSessionReq, t.BackChannelLogoutUri, t.ClientClaimsPrefix, t.ClientId, t.ClientName, t.ClientUri, t.ConsentLifetime, t.Created, t.Description, t.DeviceCodeLifetime, t.EnableLocalLogin, t.Enabled, t.FrontChannelLogoutSessionReq, t.FrontChannelLogoutUri, t.IdentityTokenLifetime, t.IncludeJwtId, t.LastAccessed, t.LogoUri, t.NonEditable, t.PairWiseSubjectSalt, t.ProtocolType, t.RefreshTokenExpiration, t.RefreshTokenUsage, t.RequireClientSecret, t.RequireConsent, t.RequirePkce, t.SlidingRefreshTokenLifetime, t.UpdateAccessTkClaimsOnRefresh, t.Updated, t.UserCodeType, t.UserSsoLifetime
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
FETCH FIRST 1 ROWS ONLY
2020-05-08 14:17:43.610 +12:00 [INF] Executed DbCommand (2ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT t.Id, t.AbsoluteRefreshTokenLifetime, t.AccessTokenLifetime, t.AccessTokenType, t.AllowAccessTokensViaBrowser, t.AllowOfflineAccess, t.AllowPlainTextPkce, t.AllowRememberConsent, t.AlwaysIncUserClaimsInIdToken, t.AlwaysSendClientClaims, t.AuthorizationCodeLifetime, t.BackChannelLogoutSessionReq, t.BackChannelLogoutUri, t.ClientClaimsPrefix, t.ClientId, t.ClientName, t.ClientUri, t.ConsentLifetime, t.Created, t.Description, t.DeviceCodeLifetime, t.EnableLocalLogin, t.Enabled, t.FrontChannelLogoutSessionReq, t.FrontChannelLogoutUri, t.IdentityTokenLifetime, t.IncludeJwtId, t.LastAccessed, t.LogoUri, t.NonEditable, t.PairWiseSubjectSalt, t.ProtocolType, t.RefreshTokenExpiration, t.RefreshTokenUsage, t.RequireClientSecret, t.RequireConsent, t.RequirePkce, t.SlidingRefreshTokenLifetime, t.UpdateAccessTkClaimsOnRefresh, t.Updated, t.UserCodeType, t.UserSsoLifetime
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
FETCH FIRST 1 ROWS ONLY
2020-05-08 14:17:43.613 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'Client' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.613 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.613 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.613 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.614 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.614 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.614 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.614 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.614 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Origin
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientCorsOrigin c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.616 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Origin
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientCorsOrigin c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.616 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientCorsOrigin' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.617 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.617 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.617 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.618 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.618 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.618 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.618 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.618 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.GrantType
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientGrantType c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.619 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.GrantType
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientGrantType c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.619 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientGrantType' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.620 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.620 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.620 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.620 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.620 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.620 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.621 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.621 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Scope
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientScope c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.622 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Scope
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientScope c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.622 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.622 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.622 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.622 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientScope' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.622 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.623 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.623 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.623 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.624 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.624 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.624 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.624 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Type, c0.Value
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientClaim c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.624 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Type, c0.Value
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientClaim c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.625 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.625 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.625 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.626 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.626 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.626 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.626 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.626 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Created, c0.Description, c0.Expiration, c0.Type, c0.Value
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientSecret c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.627 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Created, c0.Description, c0.Expiration, c0.Type, c0.Value
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientSecret c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.631 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientSecret' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.636 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.636 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.636 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.637 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.637 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.637 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.637 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.637 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Provider
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientIdPRestriction c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.638 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Provider
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientIdPRestriction c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.638 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.638 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.639 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.639 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.639 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.639 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.639 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.639 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.PostLogoutRedirectUri
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientPostLogoutRedirectUri c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.640 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.PostLogoutRedirectUri
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientPostLogoutRedirectUri c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.641 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientPostLogoutRedirectUri' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.641 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientPostLogoutRedirectUri' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.641 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.641 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.641 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.642 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.642 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.642 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.642 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.642 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Key, c0.Value
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientProperty c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.643 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.Key, c0.Value
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientProperty c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.644 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.644 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.644 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.645 +12:00 [DBG] Creating DbCommand for 'ExecuteReader'.
2020-05-08 14:17:43.645 +12:00 [DBG] Created DbCommand for 'ExecuteReader' (0ms).
2020-05-08 14:17:43.645 +12:00 [DBG] Opening connection to database '' on server 'emttest'.
2020-05-08 14:17:43.645 +12:00 [DBG] Opened connection to database '' on server 'emttest'.
2020-05-08 14:17:43.645 +12:00 [DBG] Executing DbCommand [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.RedirectUri
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientRedirectUri c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.645 +12:00 [INF] Executed DbCommand (1ms) [Parameters=[p__clientId_0='?' (Size = 8), p__p_1='?' (DbType = Int32)], CommandType='"Text"', CommandTimeout='0']
SELECT c0.Id, c0.ClientId, c0.RedirectUri
FROM (
    SELECT c.Id, c.AbsoluteRefreshTokenLifetime, c.AccessTokenLifetime, c.AccessTokenType, c.AllowAccessTokensViaBrowser, c.AllowOfflineAccess, c.AllowPlainTextPkce, c.AllowRememberConsent, c.AlwaysIncUserClaimsInIdToken, c.AlwaysSendClientClaims, c.AuthorizationCodeLifetime, c.BackChannelLogoutSessionReq, c.BackChannelLogoutUri, c.ClientClaimsPrefix, c.ClientId, c.ClientName, c.ClientUri, c.ConsentLifetime, c.Created, c.Description, c.DeviceCodeLifetime, c.EnableLocalLogin, c.Enabled, c.FrontChannelLogoutSessionReq, c.FrontChannelLogoutUri, c.IdentityTokenLifetime, c.IncludeJwtId, c.LastAccessed, c.LogoUri, c.NonEditable, c.PairWiseSubjectSalt, c.ProtocolType, c.RefreshTokenExpiration, c.RefreshTokenUsage, c.RequireClientSecret, c.RequireConsent, c.RequirePkce, c.SlidingRefreshTokenLifetime, c.UpdateAccessTkClaimsOnRefresh, c.Updated, c.UserCodeType, c.UserSsoLifetime
    FROM IDP.Clients c
    WHERE c.ClientId = :p__clientId_0
    FETCH FIRST :p__p_1 ROWS ONLY
) t
INNER JOIN IDP.ClientRedirectUri c0 ON t.Id = c0.ClientId
2020-05-08 14:17:43.648 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientRedirectUri' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.648 +12:00 [DBG] Context 'OAuthConfigDbContext' started tracking 'ClientRedirectUri' entity. Consider using 'DbContextOptionsBuilder.EnableSensitiveDataLogging' to see key values.
2020-05-08 14:17:43.648 +12:00 [DBG] A data reader was disposed.
2020-05-08 14:17:43.648 +12:00 [DBG] Closing connection to database '' on server 'emttest'.
2020-05-08 14:17:43.648 +12:00 [DBG] Closed connection to database '' on server 'emttest'.
2020-05-08 14:17:43.649 +12:00 [DBG] emt.core found in database: true
2020-05-08 14:17:43.649 +12:00 [VRB] Calling into client configuration validator: IdentityServer4.Validation.DefaultClientConfigurationValidator
2020-05-08 14:17:43.649 +12:00 [DBG] client configuration validation for client emt.core succeeded.
2020-05-08 14:17:43.649 +12:00 [VRB] Setting item in cache for emt.core
2020-05-08 14:17:43.649 +12:00 [DBG] Checking for PKCE parameters
2020-05-08 14:17:43.650 +12:00 [DBG] No PKCE used.
2020-05-08 14:17:43.650 +12:00 [VRB] Cache hit for openid,profile,emt.api.internal,emt.api.legacy
2020-05-08 14:17:43.650 +12:00 [VRB] Cache hit for openid,profile,emt.api.internal,emt.api.legacy
2020-05-08 14:17:43.651 +12:00 [VRB] Cache hit for openid,profile,emt.api.internal,emt.api.legacy
2020-05-08 14:17:43.651 +12:00 [VRB] Cache hit for openid,profile,emt.api.internal,emt.api.legacy
2020-05-08 14:17:43.651 +12:00 [DBG] Calling into custom validator: IdentityServer4.Validation.DefaultCustomAuthorizeRequestValidator
2020-05-08 14:17:43.651 +12:00 [VRB] Authorize request protocol validation successful
2020-05-08 14:17:43.651 +12:00 [DBG] ValidatedAuthorizeRequest
{"ClientId":"emt.core","ClientName":null,"RedirectUri":"https:///emtlogin.aspx","AllowedRedirectUris":["https:/login.aspx","https://login.aspx"],"SubjectId":"100000497","ResponseType":"code id_token token","ResponseMode":"form_post","GrantType":"hybrid","RequestedScopes":"openid profile internal legacy offline_access","State":"OpenIdConnect.AuthenticationProperties=TNEHTuVJsCX1oBNmxfetk5diX64PCIyKJEMlZ8hO9pfKRWrb5icykd6ix55dc36wWxwL_z1yaMBu56upc-jVC6khQkVewjTMvsyqXsZ_sNimMoN8Ou4E7R_Pra2Px2TohCU0VJrNIQLQ5oLxqf3-mbPXyOS1fyix7bmsTM_I3bJgzTiYK0IMKxHYBWHodPLTVugezTqzXAHNFotYg_ChaLWLBFIIfDXjCSanYcuD2powIsldhO0xSt_Kehl7CdufqQXuY-JXXJgS0FOt_y71S1EcNh3cpNX1AySG-zoyPNln5L98IwHWMbeMlQKrOz99OcuoN3-UvH-IoFpsF--clCIvdP0BqqJXz7zKPsVKqOu8hvEjeeTHrtAOsFva3ovRM_M68uFi4YyGJpC-xBro5f3JeUPfigaYDwx3fHkMTEM","UiLocales":null,"Nonce":"637245010635444378.YmJmMzQ0ZDctY2M4ZS00MmE3LWI1NjktOTM2ZDc5ZDEzOTI3NmFmNzIwYjYtZWI2Yy00Mjc4LWFlMTYtMzBmODliYTBlOGI0","AuthenticationContextReferenceClasses":null,"DisplayMode":null,"PromptMode":null,"MaxAge":null,"LoginHint":null,"SessionId":"xrHUgMr6I3RWTJrJ_CwxjQ","Raw":{"client_id":"core","redirect_uri":"https://login.aspx","response_mode":"form_post","response_type":"code id_token token","scope":"openid profile api.internal api.legacy offline_access","state":"OpenIdConnect.AuthenticationProperties=TNEHTuVJsCX1oBNmxfetk5diX64PCIyKJEMlZ8hO9pfKRWrb5icykd6ix55dc36wWxwL_z1yaMBu56upc-jVC6khQkVewjTMvsyqXsZ_sNimMoN8Ou4E7R_Pra2Px2TohCU0VJrNIQLQ5oLxqf3-mbPXyOS1fyix7bmsTM_I3bJgzTiYK0IMKxHYBWHodPLTVugezTqzXAHNFotYg_ChaLWLBFIIfDXjCSanYcuD2powIsldhO0xSt_Kehl7CdufqQXuY-JXXJgS0FOt_y71S1EcNh3cpNX1AySG-zoyPNln5L98IwHWMbeMlQKrOz99OcuoN3-UvH-IoFpsF--clCIvdP0BqqJXz7zKPsVKqOu8hvEjeeTHrtAOsFva3ovRM_M68uFi4YyGJpC-xBro5f3JeUPfigaYDwx3fHkMTEM","nonce":"637245010635444378.YmJmMzQ0ZDctY2M4ZS00MmE3LWI1NjktOTM2ZDc5ZDEzOTI3NmFmNzIwYjYtZWI2Yy00Mjc4LWFlMTYtMzBmODliYTBlOGI0","x-client-SKU":"ID_NET451","x-client-ver":"5.2.1.0"},"$type":"AuthorizeRequestValidationLog"}
2020-05-08 14:17:43.652 +12:00 [VRB] ProcessInteractionAsync
2020-05-08 14:17:43.652 +12:00 [DBG] Calling custom provider FindByIdAsync method.
2020-05-08 14:17:43.652 +12:00 [INF] Calling FindByIdAsync: Id: 100000497
2020-05-08 14:17:43.655 +12:00 [DBG] sys config: LDAP ismanual: False
2020-05-08 14:17:43.655 +12:00 [DBG] after FindByIdAsync: email: [email protected] Cnf:True, FLA0 PEE:False, PE-null- LEE:True LE:-null-
2020-05-08 14:17:43.655 +12:00 [INF] Showing login: User is not active
2020-05-08 14:17:43.655 +12:00 [VRB] End authorize request. result type: IdentityServer4.Endpoints.Results.LoginPageResult
2020-05-08 14:17:43.655 +12:00 [VRB] Invoking result: IdentityServer4.Endpoints.Results.LoginPageResult
2020-05-08 14:17:43.656 +12:00 [DBG] 'OAuthConfigDbContext' disposed.
2020-05-08 14:17:43.656 +12:00 [DBG] 'ApplicationDbContext' disposed.
2020-05-08 14:17:43.656 +12:00 [INF] Request finished in 62.819ms 302 
2020-05-08 14:17:43.671 +12:00 [INF] Request starting HTTP/2.0 GET https://test.com/emtidm/Account/Login?ReturnUrl=%2Fidm%2Fconnect%2Fauthorize%2Fcallback%3Fclient_id%3Demt.core%26redirect_uri%3Dhttps%253A%252F%252Ftest.com%252Femt%252Femtlogin.aspx%26response_mode%3Dform_post%26response_type%3Dcode%2520id_token%2520token%26scope%3Dopenid%2520profile%2520emt.api.internal%2520emt.api.legacy%2520offline_access%26state%3DOpenIdConnect.AuthenticationProperties%253DTNEHTuVJsCX1oBNmxfetk5diX64PCIyKJEMlZ8hO9pfKRWrb5icykd6ix55dc36wWxwL_z1yaMBu56upc-jVC6khQkVewjTMvsyqXsZ_sNimMoN8Ou4E7R_Pra2Px2TohCU0VJrNIQLQ5oLxqf3-mbPXyOS1fyix7bmsTM_I3bJgzTiYK0IMKxHYBWHodPLTVugezTqzXAHNFotYg_ChaLWLBFIIfDXjCSanYcuD2powIsldhO0xSt_Kehl7CdufqQXuY-JXXJgS0FOt_y71S1EcNh3cpNX1AySG-zoyPNln5L98IwHWMbeMlQKrOz99OcuoN3-UvH-IoFpsF--clCIvdP0BqqJXz7zKPsVKqOu8hvEjeeTHrtAOsFva3ovRM_M68uFi4YyGJpC-xBro5f3JeUPfigaYDwx3fHkMTEM%26nonce%3D637245010635444378.YmJmMzQ0ZDctY2M4ZS00MmE3LWI1NjktOTM2ZDc5ZDEzOTI3NmFmNzIwYjYtZWI2Yy00Mjc4LWFlMTYtMzBmODliYTBlOGI0%26x-client-SKU%3DID_NET451%26x-client-ver%3D5.2.1.0  
2020-05-08 14:17:43.671 +12:00 [VRB] All hosts are allowed.
2020-05-08 14:17:43.671 +12:00 [VRB] Adding HSTS header to response.
2020-05-08 14:17:43.671 +12:00 [VRB] Adding HSTS header to response.
2020-05-08 14:17:43.671 +12:00 [DBG] The request path /Account/Login does not match a supported file type
2020-05-08 14:17:43.672 +12:00 [DBG] 1 candidate(s) found for the request path '/Account/Login'
2020-05-08 14:17:43.672 +12:00 [DBG] Endpoint 'AC.Auth.Server.Controllers.AccountController.Login (AC.Auth.Server)' with route pattern '{controller=account}/{action=login}/{id?}' is valid for the request path '/Account/Login'
2020-05-08 14:17:43.672 +12:00 [DBG] Request matched endpoint 'AC.Auth.Server.Controllers.AccountController.Login (AC.Auth.Server)'
2020-05-08 14:17:43.672 +12:00 [VRB] Performing unprotect operation to key {590c83d6-1e15-4bfc-aadf-d9a48b674461} with purposes ('IdentityManagementService', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Identity.Application', 'v2').
2020-05-08 14:17:43.673 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.674 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.675 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.675 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.675 +12:00 [VRB] returnUrl is valid
2020-05-08 14:17:43.675 +12:00 [VRB] returnUrl is valid
endless loop until it hits the stack overflow
@brockallen
Copy link
Contributor

Can you reproduce this using one of our samples?

@jmatheti
Copy link
Author

Let me give that a try today and get back here with an update.

@jmatheti
Copy link
Author

jmatheti commented Jul 6, 2020

@brockallen Apologies for the delay in getting back.

Unfortunately I am unable to re-produce the issue with the quick start. But I know the usecase that caused this loop.

  1. Login on client A with an account on the Identityserver that is using the aspnetIdentity. The profile service- IsActive is context.IsActive = user != null && !isUserLockedOut ;.
  2. Lock the account with incorrect password attempts on a different browser session.
  3. Try to login on client B within the same browser (where Client A user is loggedin) . assuming ClientB is initiating the authorization request to above IDM server.

Tried the below steps to reproduce the issue

  1. Using main/src/AspNetIdentity/IdentityServer4.AspNetIdentity.sln.

  2. Modify the startup to include the fluentvalidation and LabelService, like here

  3. Add [LoginViewModelValidator](https://github.com/Janidbest/4386/blob/master/LoginViewModelValidator.cs) and [LabelService](https://github.com/Janidbest/4386/blob/master/LabelService.cs) [ILabelService](https://github.com/Janidbest/4386/blob/master/ILabelService.cs)

  4. Update the ProfileService IsActive - to check if user is not locked out only.

  5. Run

  6. Open Clients

  7. Updated the Authority constant from http://5000 link to https:xxxx

  8. Run MVCImplicit and MVC hybrid two clients

  9. Then Login by clicking secure on MVCImplicit sample client

  10. Lock the user account.

  11. Then open MVCHybrid client within same browser session where already logged in.

Notice the user presented with a login screen,as per the profile Service Is Active context (but the user is already logged in - from the auth cookie in the request).

in our case, when we tried to login on the Client B, that was causing the stack over flow exception with the endless loop.

After we replaced the LabelService constructor code https://github.com/Janidbest/4386/blob/master/LabelService.cs with a local method that extracts the clientId from the URL, the issue was disappeared.

@brockallen
Copy link
Contributor

Perhaps related? #4644 If it's the same, then we can close this issue as a PR has been submitted.

@jmatheti
Copy link
Author

I am not sure, this issue is not involving the external authentication provider. But we have the following in the GET Login action method
// Clear the existing external cookie to ensure a clean login process await HttpContext.SignOutAsync(IdentityConstants.ExternalScheme);

Since the ProfileService - IsActiveAsync is setting the IsActiveContext to false, so the identityservices are challenge the authentication as a result the Login must have initiated, which case the above code will be executing.

So, if the issue is in the HttpContext.SignOutAsync(IdentityConstants.ExternalScheme) method with a valid cookie in the request, then yes, it is related.

@brockallen
Copy link
Contributor

Closing. If you still have issues, feel free to reopen.

@github-actions
Copy link

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Nov 26, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@brockallen brockallen

Labels
bug report question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@brockallen @jmatheti