INVALID_PROXY_CALLBACK error on "/proxyValidate" callback, after successful initial authentication

[Jordanab]

Hello,

I've been trying to get CAS (5.3.0) working for the last couple of days. Following the documentation I've been able to package it (using the Maven Overlay), and get it running along with JDBC. When I login with my test credentials, I can see in the logs (and Fiddler HTTP proxy) that I'm authenticated successfully, a ticket is created and I'm redirected back to the application. However when the application does a "/proxyValidate" callback to CAS, it fails, returning a INVALID_PROXY_CALLBACK error. Looking through the logs I can see that the QueryDatabaseAuthenticationHandler does not seem to recognize/support the credentials being passed into it.

Log notifications related to the initial successful authentication:

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [SimplePrincipal(id=testuser, attributes={})] for inclusion in result>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{}] for inclusion in this result for principal [testuser]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [credentialType] -> [UsernamePasswordCredential]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [QueryDatabaseAuthenticationHandler]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[QueryDatabaseAuthenticationHandler]]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{credentialType=UsernamePasswordCredential, authenticationMethod=QueryDatabaseAuthenticationHandler, successfulAuthenticationHandlers=[QueryDatabaseAuthenticationHandler]}] for inclusion in this authentication result>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationBuilder] - <Recording authentication handler result success under key [QueryDatabaseAuthenticationHandler]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [SimplePrincipal(id=testuser, attributes={})] as the primary principal>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [SimplePrincipal(id=testuser, attributes={})]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{credentialType=UsernamePasswordCredential, authenticationMethod=QueryDatabaseAuthenticationHandler, successfulAuthenticationHandlers=[QueryDatabaseAuthenticationHandler]}]>

2018-07-09 20:35:00,609 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2018-07-09T20:35:00.609+02:00[Europe/Berlin]]>

2018-07-09 20:35:00,625 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication [org.apereo.cas.authentication.DefaultAuthentication@4a87ed80] and service [AbstractWebApplicationService(id=https://app.testdomain.local/, originalUrl=https://app.testdomain.local/, artifactId=null, principal=null, source=service, loggedOutAlready=false, format=XML, attributes={})]>

Log notifications related to the failed /proxyValidate callback:

2018-07-09 20:35:00,890 DEBUG [org.apereo.cas.authentication.PseudoPlatformTransactionManager] - <Creating new transaction with name [org.apereo.cas.DefaultCentralAuthenticationService.getTicket]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; 'ticketTransactionManager',+org.apereo.cas.ticket.InvalidTicketException>

2018-07-09 20:35:00,890 DEBUG [org.apereo.cas.ticket.registry.AbstractTicketRegistry] - <Encoded original ticket id [ST-1-fkKcupXw88CtL6lJghlycHKXhD0TEST-INSTANCE] to [ddd60a4514b23493f16239ee7c76f16f5941c0938d0f5466015a99100ee6722bb0905beabe02b408f3e8337cdba94bd57d05a387033d5e355b7cf074781accfe]>

2018-07-09 20:35:00,890 DEBUG [org.apereo.cas.ticket.registry.AbstractTicketRegistry] - <Attempting to decode [EncodedTicket(id=ddd60a4514b23493f16239ee7c76f16f5941c0938d0f5466015a99100ee6722bb0905beabe02b408f3e8337cdba94bd57d05a387033d5e355b7cf074781accfe)]>

2018-07-09 20:35:00,890 DEBUG [org.apereo.cas.ticket.registry.AbstractTicketRegistry] - <Decoded ticket to [ST-1-fkKcupXw88CtL6lJghlycHKXhD0TEST-INSTANCE]>

2018-07-09 20:35:00,890 DEBUG [org.apereo.cas.authentication.PseudoPlatformTransactionManager] - <Initiating transaction commit>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Invoking authentication pre processors for authentication transaction>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationEventExecutionPlan] - <Sorted and registered authentication pre processors for this transaction are [[]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication credentials provided for this transaction are [[AbstractCredential()]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Candidate/Registered authentication handlers for this transaction are [[org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@7d0f06, org.apereo.cas.adaptors.jdbc.QueryDatabaseAuthenticationHandler@436b9330]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationEventExecutionPlan] - <Sorted and registered authentication handler resolvers for this transaction are [[org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver@6e254bcb]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication handler resolvers for this transaction are [[org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver@6e254bcb]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Located registered service definition [AbstractRegisteredService(serviceId=^(https|imaps)://.*, name=HTTPS and IMAPS, theme=null, informationUrl=null, privacyUrl=null, responseType=null, id=10000001, description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols., expirationPolicy=DefaultRegisteredServiceExpirationPolicy(deleteWhenExpired=false, notifyWhenDeleted=false, expirationDate=null), proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@1, evaluationOrder=10000, usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@87297e2, logoutType=BACK_CHANNEL, requiredHandlers=[], attributeReleasePolicy=ReturnAllowedAttributeReleasePolicy(super=AbstractRegisteredServiceAttributeReleasePolicy(attributeFilter=null, principalAttributesRepository=DefaultPrincipalAttributesRepository(), consentPolicy=DefaultRegisteredServiceConsentPolicy(enabled=true, excludedAttributes=null, includeOnlyAttributes=null), authorizedToReleaseCredentialPassword=false, authorizedToReleaseProxyGrantingTicket=false, excludeDefaultAttributes=false, authorizedToReleaseAuthenticationAttributes=true, principalIdAttribute=null), allowedAttributes=[]), multifactorPolicy=DefaultRegisteredServiceMultifactorPolicy(multifactorAuthenticationProviders=[], failureMode=NOT_SET, principalAttributeNameTrigger=null, principalAttributeValueToMatch=null, bypassEnabled=false), logo=null, logoutUrl=null, accessStrategy=DefaultRegisteredServiceAccessStrategy(order=0, enabled=true, ssoEnabled=true, unauthorizedRedirectUrl=null, delegatedAuthenticationPolicy=DefaultRegisteredServiceDelegatedAuthenticationPolicy(allowedProviders=[]), requireAllAttributes=true, requiredAttributes={}, rejectedAttributes={}, caseInsensitive=false), publicKey=null, properties={}, contacts=[])] for this authentication transaction>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication handler resolvers produced no candidate authentication handler. Using the default handler resolver instead...>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.AuthenticationHandlerResolver] - <Default authentication handlers used for this transaction are [HttpBasedServiceCredentialsAuthenticationHandler,QueryDatabaseAuthenticationHandler]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Resolved and finalized authentication handlers to carry out this authentication transaction are [[org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver@6e254bcb]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Candidate resolved authentication handlers for this transaction are [[org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@7d0f06, org.apereo.cas.adaptors.jdbc.QueryDatabaseAuthenticationHandler@436b9330]]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Attempting to authenticate credential [AbstractCredential()]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Attempting authentication of [https://app.testdomain.local/?proxyResponse=true] using [HttpBasedServiceCredentialsAuthenticationHandler]>

2018-07-09 20:35:00,907 WARN [org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler] - <Proxy policy for service [^(https|imaps)://.*] cannot authorize the requested callback url [https://app.testdomain.local/?proxyResponse=true].>

2018-07-09 20:35:00,907 ERROR [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication has failed. Credentials may be incorrect or CAS cannot find authentication handler that supports [AbstractCredential()] of type [HttpBasedServiceCredential]. Examine the configuration to ensure a method of authentication is defined and analyze CAS logs at DEBUG level to trace the authentication event.>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <[HttpBasedServiceCredentialsAuthenticationHandler] exception details: [https://app.testdomain.local/?proxyResponse=true cannot be authorized].>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationBuilder] - <Recording authentication handler failure under key [HttpBasedServiceCredentialsAuthenticationHandler]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.handler.support.AbstractUsernamePasswordAuthenticationHandler] - <Credential is not one of username/password and is not accepted by handler [QueryDatabaseAuthenticationHandler]>

2018-07-09 20:35:00,907 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication handler [QueryDatabaseAuthenticationHandler] does not support the credential type [AbstractCredential()]. Trying next...>

2018-07-09 20:35:00,925 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN

I've been struggling with this for a couple of days now, to no avail. Any help/hints would be greatly appreciated.

Regards,

Jordan.

[Jordanab]

Finally did manage to solve it, after stumbling on this doc page: https://apereo.github.io/cas/5.0.x/installation/Configuring-Service-Proxy-Policy.html. I needed to define a proxy authentication policy in my service definition.

Regards,

Jordan.