OAuth cannot validate service ticket?
185 views
Skip to first unread message
Baron Fujimoto
Sep 4, 2018, 11:53:11 PM9/4/18
to CAS Users
I'm trying to help a developer use OAuth with our 5.0.x instance. I believe I've successfully enabled the OAuth feature documentation at <https://apereo.github.io/cas/5.0.x/installation/OAuth-OpenId-Authentication.html>
Our barebones service registration for their service looks like:
{
"name" : "OAuth_test",
"clientId" : "OAuth_test",
"clientSecret": "*****",
"serviceId" : "^http://.*",
"description" : "OAuth test",
"id" : 201809041700,
"bypassApprovalPrompt": false,
"@class" : "org.apereo.cas.support.oauth.services.OAuthRegisteredService",
}
However the client, after authenticating the user, eventually throws up the error, "Error: cannot validate CAS ticket: ST-1-0pzfaTQ9HGcmk64kIU9t-cas", and I see an exception in the logs that ultimately seems to boild down to:
Caused by: org.jasig.cas.client.validation.TicketValidationException: No principal was found in the response from the CAS server.
I notice in the logs that the request appears to call /cas/oauth2.0/callbackAuthorize, which I don't see as an endpoint in the CAS OAuth documentation. Is this significant?
More specifically, the client appears to be using the service
http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas
Can anyone provide any pointers to what's going on here? My Google-fu has been weak trying to get traction on this.
--
Baron Fujimoto <ba...@hawaii.edu> :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum
Our barebones service registration for their service looks like:
{
"name" : "OAuth_test",
"clientId" : "OAuth_test",
"clientSecret": "*****",
"serviceId" : "^http://.*",
"description" : "OAuth test",
"id" : 201809041700,
"bypassApprovalPrompt": false,
"@class" : "org.apereo.cas.support.oauth.services.OAuthRegisteredService",
}
However the client, after authenticating the user, eventually throws up the error, "Error: cannot validate CAS ticket: ST-1-0pzfaTQ9HGcmk64kIU9t-cas", and I see an exception in the logs that ultimately seems to boild down to:
Caused by: org.jasig.cas.client.validation.TicketValidationException: No principal was found in the response from the CAS server.
I notice in the logs that the request appears to call /cas/oauth2.0/callbackAuthorize, which I don't see as an endpoint in the CAS OAuth documentation. Is this significant?
More specifically, the client appears to be using the service
http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas
Can anyone provide any pointers to what's going on here? My Google-fu has been weak trying to get traction on this.
--
Baron Fujimoto <ba...@hawaii.edu> :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum
Andy Ng
Sep 5, 2018, 4:10:00 AM9/5/18
to CAS Community
Hi Baron,
Maybe some more debug logs will helps with debugging this issue?
/cas/oauth2.0/callbackAuthorize is an intermediate URL, usually no need to know about it. So that why the doc didn't specified it.
Maybe you can try upgrading it to CAS 5.3 and see if the problem still exists. CAS OAuth implementation is a lot more stable in 5.2 / 5.3 versions in my opinion.
Cheers!
- Andy
Baron Fujimoto
Sep 5, 2018, 2:58:17 PM9/5/18
to cas-...@apereo.org
Happy to provide more debug logs. Since the logs at DEBUG level are so verbose I tried to excerpt what I thought would be relevant. Any suggestions on anything in particular?
Unfortunately, while we have medium to longer term plans to upgrade to 5.3, upgrading from 5.0 is not an option in the short term.
On Wed, Sep 05, 2018 at 01:09:59AM -0700, Andy Ng wrote:
>Hi Baron,
>
>Maybe some more debug logs will helps with debugging this issue?
>
>*/cas/oauth2.0/callbackAuthorize* is an intermediate URL, usually no need
>> Baron Fujimoto <ba...@hawaii.edu <javascript:>> :: UH Information
>- Website: https://apereo.github.io/cas
>- Gitter Chatroom: https://gitter.im/apereo/cas
>- List Guidelines: https://goo.gl/1VRrw7
>- Contributions: https://goo.gl/mh7qDG
>---
>You received this message because you are subscribed to the Google Groups "CAS Community" group.
>To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
>To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/2ae1bd11-5fd6-461c-9be5-e7200ca2d550%40apereo.org.
Unfortunately, while we have medium to longer term plans to upgrade to 5.3, upgrading from 5.0 is not an option in the short term.
On Wed, Sep 05, 2018 at 01:09:59AM -0700, Andy Ng wrote:
>Hi Baron,
>
>Maybe some more debug logs will helps with debugging this issue?
>
>> Technology Services
>> minutas cantorum, minutas balorum, minutas carboratum desendus pantorum
>>
>
>--
>> minutas cantorum, minutas balorum, minutas carboratum desendus pantorum
>>
>
>- Website: https://apereo.github.io/cas
>- Gitter Chatroom: https://gitter.im/apereo/cas
>- List Guidelines: https://goo.gl/1VRrw7
>- Contributions: https://goo.gl/mh7qDG
>---
>You received this message because you are subscribed to the Google Groups "CAS Community" group.
>To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
>To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/2ae1bd11-5fd6-461c-9be5-e7200ca2d550%40apereo.org.
Baron Fujimoto
Sep 5, 2018, 4:23:10 PM9/5/18
to cas-...@apereo.org
Here are the debug logs for the client's attempt. I've just redacted some of the potentially sensitive local info and hazelcast related entries.
2018-09-05 09:11:23,754 DEBUG [org.apereo.cas.support.oauth.DefaultOAuthCasClientRedirectActionBuilder] - <Final redirect url is http://cas.example.edu/cas/login?service=http%3A%2F%2Fcas.example.edu%2Fcas%2Foauth2.0%2FcallbackAuthorize%3Fclient_name%3DCasOAuthClient%26client_id%3DOAuth_test%26redirect_uri%3Dhttp%3A%2F%2Flocalhost%3A8080%2Flogin%2Fcas>
2018-09-05 09:11:23,787 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2018-09-05 09:11:23,788 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@5f44f10e>
2018-09-05 09:11:23,789 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:23,789 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^http://.* is a valid regex.>
2018-09-05 09:11:23,790 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:23,800 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2018-09-05 09:11:23,803 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@5f44f10e>
2018-09-05 09:11:23,804 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:24,676 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages_en] - neither plain properties nor XML>
2018-09-05 09:11:24,677 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages] - neither plain properties nor XML>
2018-09-05 09:11:24,678 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:messages_en] - neither plain properties nor XML>
2018-09-05 09:11:24,679 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <Re-caching properties for filename [classpath:messages] - file hasn't been modified>
2018-09-05 09:11:29,927 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2018-09-05 09:11:29,931 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@5f44f10e>
2018-09-05 09:11:29,931 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Located client IP address as nnn.nnn.nnn.nnn>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <User agent Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36 is authorized to proceed>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Adaptive authentication policy has authorized client nnn.nnn.nnn.nnn to proceed.>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:29,939 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:29,959 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.adaptors.duo.authn.api.DuoApiAuthenticationHandler@7051b1f7, org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@70efdca7, org.apereo.cas.adaptors.duo.authn.web.DuoAuthenticationHandler@70253ce, org.apereo.cas.authentication.LdapAuthenticationHandler@2bf516da]>
2018-09-05 09:11:29,963 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Attempting LDAP authentication for userfoo>
2018-09-05 09:11:29,968 WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler] - <Operation exception encountered, reopening connection>
2018-09-05 09:11:30,026 WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler] - <Operation exception encountered, reopening connection>
2018-09-05 09:11:30,079 WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler] - <Operation exception encountered, reopening connection>
2018-09-05 09:11:30,130 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response: [org.ldaptive.auth.AuthenticationResponse@1382127251::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=***...***,ou=People,dc=example,dc=edu, ldapEntry=[dn=***...***,ou=People,dc=example,dc=edu[[uid[userfoo]], [mail[use...@example.edu]], ...], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2018-09-05 09:11:30,131 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Applying password policy to [org.ldaptive.auth.AuthenticationResponse@1382127251::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=***...***,ou=People,dc=example,dc=edu, ldapEntry=[dn=***...***,ou=People,dc=example,dc=edu[[uid[userfoo]], [mail[use...@example.edu]], ...], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2018-09-05 09:11:30,139 DEBUG [org.apereo.cas.authentication.support.DefaultAccountStateHandler] - <Account state not defined. Returning empty list of messages.>
2018-09-05 09:11:30,139 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response returned as result. Creating the final LDAP principal>
2018-09-05 09:11:30,140 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Creating LDAP principal for userfoo based on ***...***,ou=People,dc=example,dc=edu>
2018-09-05 09:11:30,140 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Principal id attribute is not defined. Using the default provided user id userfoo>
2018-09-05 09:11:30,140 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [mail[use...@example.edu]]>
2018-09-05 09:11:30,149 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Created LDAP principal for id userfoo and 10 attributes>
2018-09-05 09:11:30,149 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated userfoo>
2018-09-05 09:11:30,149 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <No resolver configured for LdapAuthenticationHandler. Falling back to handler principal userfoo>
2018-09-05 09:11:30,150 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is userfoo>
2018-09-05 09:11:30,150 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2018-09-05 09:11:30,151 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated principal [userfoo] and attributes {..., LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, uid=userfoo} with credentials [userfoo].>
2018-09-05 09:11:30,152 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Authentication org.apereo.cas.authentication.AbstractAuthenticationManager.authenticate(AuthenticationTransaction))]>
2018-09-05 09:11:30,158 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: Supplied credentials: [userfoo]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,173 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@a40446df]>
2018-09-05 09:11:30,176 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,176 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,176 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,178 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,178 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [userfoo] for inclusion in result>
2018-09-05 09:11:30,180 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=userfoo, LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ... }] for inclusion in this result for principal [userfoo]>
2018-09-05 09:11:30,180 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [samlAuthenticationStatementAuthMethod] -> [urn:oasis:names:tc:SAML:1.0:am:password]>
2018-09-05 09:11:30,180 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [userfoo] as the primary principal>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [userfoo]>
2018-09-05 09:11:30,182 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2018-09-05 09:11:30,182 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2018-09-05T09:11:30.182-10:00[Pacific/Johnston]]>
2018-09-05 09:11:30,182 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@e41f41f and service http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:30,185 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for userfoo>
2018-09-05 09:11:30,186 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}]>
2018-09-05 09:11:30,186 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [10] cached attributes for principal [userfoo] that are {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,186 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo} for userfoo>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for userfoo>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for userfoo>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2018-09-05 09:11:30,190 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: [mail, uid, ...]>
2018-09-05 09:11:30,191 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: mail>
2018-09-05 09:11:30,191 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: uid>
2018-09-05 09:11:30,193 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,193 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2018-09-05 09:11:30,194 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2018-09-05 09:11:30,194 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2018-09-05 09:11:30,194 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,195 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2018-09-05 09:11:30,203 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasTicketGrantingTicketCreatedEvent@64eeb930[ticketGrantingTicket=TGT-**********************************************0jaimUC4eF-cas]>
2018-09-05 09:11:30,205 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(TicketGrantingTicket org.apereo.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket(AuthenticationResult))]>
2018-09-05 09:11:30,207 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: TGT-**********************************************0jaimUC4eF-cas
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,207 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: TGT-**********************************************0jaimUC4eF-cas
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,261 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-**********************************************0jaimUC...@nnn.nnn.nnn.nnn@Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36]>
2018-09-05 09:11:30,264 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Encrypting via [A128CBC-HS256]>
2018-09-05 09:11:30,264 DEBUG [org.apereo.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Added cookie with name [TGC] and value [eyJh****H8nw]>
2018-09-05 09:11:30,273 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2018-09-05 09:11:30,273 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [userfoo] for inclusion in result>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=userfoo, LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ...}] for inclusion in this result for principal [userfoo]>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [samlAuthenticationStatementAuthMethod] -> [urn:oasis:names:tc:SAML:1.0:am:password]>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [userfoo] as the primary principal>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [userfoo]>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2018-09-05T09:11:30.280-10:00[Pacific/Johnston]]>
2018-09-05 09:11:30,281 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@db3e8f9f and service http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:30,283 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for userfoo>
2018-09-05 09:11:30,287 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}]>
2018-09-05 09:11:30,287 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [10] cached attributes for principal [userfoo] that are {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo} for userfoo>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for userfoo>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for userfoo>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2018-09-05 09:11:30,291 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2018-09-05 09:11:30,291 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: [mail, uid, ...]>
2018-09-05 09:11:30,293 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: mail>
2018-09-05 09:11:30,293 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: uid>
2018-09-05 09:11:30,295 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,295 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2018-09-05 09:11:30,297 DEBUG [org.apereo.cas.services.RegisteredServiceAccessStrategyUtils] - <Current authentication via ticket TGT-**********************************************0jaimUC4eF-cas allows service http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas to participate in the existing SSO session>
2018-09-05 09:11:30,297 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Looking up service ticket id generator for [org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2018-09-05 09:11:30,297 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Attempting to encode service ticket ST-3-BIFc10BUP5tlytlicB1A-cas>
2018-09-05 09:11:30,298 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Encoded service ticket id ST-3-BIFc10BUP5tlytlicB1A-cas>
2018-09-05 09:11:30,317 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-3-BIFc10BUP5tlytlicB1A-cas] for service [http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas] and principal [userfoo]>
2018-09-05 09:11:30,317 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketGrantedEvent@6c099283[ticketGrantingTicket=TGT-**********************************************0jaimUC4eF-cas,serviceTicket=ST-3-BIFc10BUP5tlytlicB1A-cas]>
2018-09-05 09:11:30,317 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(ServiceTicket org.apereo.cas.CentralAuthenticationServiceImpl.grantServiceTicket(String,Service,AuthenticationResult))]>
2018-09-05 09:11:30,318 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: ST-3-BIFc10BUP5tlytlicB1A-cas for http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,324 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Decrypting value...>
2018-09-05 09:11:30,325 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Decoded cookie value is [TGT-**********************************************0jaimUC...@nnn.nnn.nnn.nnn@Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36]>
2018-09-05 09:11:30,432 DEBUG [org.apereo.cas.web.FlowExecutionExceptionResolver] - <Ignoring the received exception due to a type mismatch>
org.pac4j.core.exception.TechnicalException: cannot validate CAS ticket: ST-3-BIFc10BUP5tlytlicB1A-cas
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:76) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:26) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClientV2.retrieveCredentials(IndirectClientV2.java:49) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClient.getCredentials(IndirectClient.java:106) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.engine.DefaultCallbackLogic.perform(DefaultCallbackLogic.java:77) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.springframework.web.CallbackController.callback(CallbackController.java:53) ~[spring-webmvc-pac4j-1.1.4.jar:?]
at org.apereo.cas.support.oauth.web.OAuth20CallbackAuthorizeController.handleRequestInternal(OAuth20CallbackAuthorizeController.java:45) ~[cas-server-support-oauth-5.0.10.jar:5.0.10]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_172]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_172]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:220) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) ~[servlet-api.jar:?]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) ~[servlet-api.jar:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.web.support.CurrentCredentialsAndAuthenticationClearingFilter.doFilter(CurrentCredentialsAndAuthenticationClearingFilter.java:28) ~[cas-server-core-web-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.RequestParameterPolicyEnforcementFilter.doFilter(RequestParameterPolicyEnforcementFilter.java:261) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.ResponseHeadersEnforcementFilter.doFilter(ResponseHeadersEnforcementFilter.java:238) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:105) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.logging.web.ThreadContextMDCServletFilter.doFilter(ThreadContextMDCServletFilter.java:90) ~[cas-server-core-logging-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:107) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:61) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:92) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:110) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:64) ~[inspektr-common-1.7.GA.jar:1.7.GA]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) ~[log4j-web-2.6.2.jar:2.6.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[catalina.jar:8.5.31]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:613) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) ~[catalina.jar:8.5.31]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) ~[catalina.jar:8.5.31]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-coyote.jar:8.5.31]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_172]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_172]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:8.5.31]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
at org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:201) ~[cas-client-core-3.4.1.jar:3.4.1]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:60) ~[pac4j-cas-1.9.7.jar:?]
... 94 more
2018-09-05 09:11:30,432 ERROR [org.springframework.boot.web.support.ErrorPageFilter] - <Forwarding to error page from request [/oauth2.0/callbackAuthorize] due to exception [cannot validate CAS ticket: ST-3-BIFc10BUP5tlytlicB1A-cas]>
org.pac4j.core.exception.TechnicalException: cannot validate CAS ticket: ST-3-BIFc10BUP5tlytlicB1A-cas
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:76) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:26) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClientV2.retrieveCredentials(IndirectClientV2.java:49) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClient.getCredentials(IndirectClient.java:106) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.engine.DefaultCallbackLogic.perform(DefaultCallbackLogic.java:77) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.springframework.web.CallbackController.callback(CallbackController.java:53) ~[spring-webmvc-pac4j-1.1.4.jar:?]
at org.apereo.cas.support.oauth.web.OAuth20CallbackAuthorizeController.handleRequestInternal(OAuth20CallbackAuthorizeController.java:45) ~[cas-server-support-oauth-5.0.10.jar:5.0.10]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_172]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_172]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:220) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) ~[servlet-api.jar:?]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) ~[servlet-api.jar:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.web.support.CurrentCredentialsAndAuthenticationClearingFilter.doFilter(CurrentCredentialsAndAuthenticationClearingFilter.java:28) ~[cas-server-core-web-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.RequestParameterPolicyEnforcementFilter.doFilter(RequestParameterPolicyEnforcementFilter.java:261) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.ResponseHeadersEnforcementFilter.doFilter(ResponseHeadersEnforcementFilter.java:238) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:105) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.logging.web.ThreadContextMDCServletFilter.doFilter(ThreadContextMDCServletFilter.java:90) ~[cas-server-core-logging-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:107) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:61) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:92) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:110) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:64) ~[inspektr-common-1.7.GA.jar:1.7.GA]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) ~[log4j-web-2.6.2.jar:2.6.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[catalina.jar:8.5.31]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:613) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) ~[catalina.jar:8.5.31]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) ~[catalina.jar:8.5.31]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-coyote.jar:8.5.31]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_172]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_172]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:8.5.31]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
at org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:201) ~[cas-client-core-3.4.1.jar:3.4.1]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:60) ~[pac4j-cas-1.9.7.jar:?]
... 94 more
Baron Fujimoto <ba...@hawaii.edu> :: UH Information Technology Services
2018-09-05 09:11:23,754 DEBUG [org.apereo.cas.support.oauth.DefaultOAuthCasClientRedirectActionBuilder] - <Final redirect url is http://cas.example.edu/cas/login?service=http%3A%2F%2Fcas.example.edu%2Fcas%2Foauth2.0%2FcallbackAuthorize%3Fclient_name%3DCasOAuthClient%26client_id%3DOAuth_test%26redirect_uri%3Dhttp%3A%2F%2Flocalhost%3A8080%2Flogin%2Fcas>
2018-09-05 09:11:23,787 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2018-09-05 09:11:23,788 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@5f44f10e>
2018-09-05 09:11:23,789 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:23,789 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^http://.* is a valid regex.>
2018-09-05 09:11:23,790 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:23,800 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2018-09-05 09:11:23,803 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@5f44f10e>
2018-09-05 09:11:23,804 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:24,676 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages_en] - neither plain properties nor XML>
2018-09-05 09:11:24,677 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages] - neither plain properties nor XML>
2018-09-05 09:11:24,678 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:messages_en] - neither plain properties nor XML>
2018-09-05 09:11:24,679 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <Re-caching properties for filename [classpath:messages] - file hasn't been modified>
2018-09-05 09:11:29,927 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2018-09-05 09:11:29,931 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@5f44f10e>
2018-09-05 09:11:29,931 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Located client IP address as nnn.nnn.nnn.nnn>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <User agent Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36 is authorized to proceed>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Adaptive authentication policy has authorized client nnn.nnn.nnn.nnn to proceed.>
2018-09-05 09:11:29,934 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:29,939 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:29,959 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.adaptors.duo.authn.api.DuoApiAuthenticationHandler@7051b1f7, org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@70efdca7, org.apereo.cas.adaptors.duo.authn.web.DuoAuthenticationHandler@70253ce, org.apereo.cas.authentication.LdapAuthenticationHandler@2bf516da]>
2018-09-05 09:11:29,963 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Attempting LDAP authentication for userfoo>
2018-09-05 09:11:29,968 WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler] - <Operation exception encountered, reopening connection>
2018-09-05 09:11:30,026 WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler] - <Operation exception encountered, reopening connection>
2018-09-05 09:11:30,079 WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler] - <Operation exception encountered, reopening connection>
2018-09-05 09:11:30,130 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response: [org.ldaptive.auth.AuthenticationResponse@1382127251::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=***...***,ou=People,dc=example,dc=edu, ldapEntry=[dn=***...***,ou=People,dc=example,dc=edu[[uid[userfoo]], [mail[use...@example.edu]], ...], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2018-09-05 09:11:30,131 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Applying password policy to [org.ldaptive.auth.AuthenticationResponse@1382127251::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=***...***,ou=People,dc=example,dc=edu, ldapEntry=[dn=***...***,ou=People,dc=example,dc=edu[[uid[userfoo]], [mail[use...@example.edu]], ...], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2018-09-05 09:11:30,139 DEBUG [org.apereo.cas.authentication.support.DefaultAccountStateHandler] - <Account state not defined. Returning empty list of messages.>
2018-09-05 09:11:30,139 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response returned as result. Creating the final LDAP principal>
2018-09-05 09:11:30,140 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Creating LDAP principal for userfoo based on ***...***,ou=People,dc=example,dc=edu>
2018-09-05 09:11:30,140 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Principal id attribute is not defined. Using the default provided user id userfoo>
2018-09-05 09:11:30,140 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [mail[use...@example.edu]]>
2018-09-05 09:11:30,149 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Created LDAP principal for id userfoo and 10 attributes>
2018-09-05 09:11:30,149 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated userfoo>
2018-09-05 09:11:30,149 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <No resolver configured for LdapAuthenticationHandler. Falling back to handler principal userfoo>
2018-09-05 09:11:30,150 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is userfoo>
2018-09-05 09:11:30,150 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2018-09-05 09:11:30,151 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated principal [userfoo] and attributes {..., LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, uid=userfoo} with credentials [userfoo].>
2018-09-05 09:11:30,152 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Authentication org.apereo.cas.authentication.AbstractAuthenticationManager.authenticate(AuthenticationTransaction))]>
2018-09-05 09:11:30,158 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: Supplied credentials: [userfoo]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,173 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@a40446df]>
2018-09-05 09:11:30,176 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,176 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,176 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,178 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,178 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2018-09-05 09:11:30,179 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [userfoo] for inclusion in result>
2018-09-05 09:11:30,180 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=userfoo, LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ... }] for inclusion in this result for principal [userfoo]>
2018-09-05 09:11:30,180 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [samlAuthenticationStatementAuthMethod] -> [urn:oasis:names:tc:SAML:1.0:am:password]>
2018-09-05 09:11:30,180 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [userfoo] as the primary principal>
2018-09-05 09:11:30,181 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [userfoo]>
2018-09-05 09:11:30,182 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2018-09-05 09:11:30,182 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2018-09-05T09:11:30.182-10:00[Pacific/Johnston]]>
2018-09-05 09:11:30,182 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@e41f41f and service http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:30,185 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for userfoo>
2018-09-05 09:11:30,186 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}]>
2018-09-05 09:11:30,186 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [10] cached attributes for principal [userfoo] that are {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,186 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo} for userfoo>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for userfoo>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for userfoo>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2018-09-05 09:11:30,187 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2018-09-05 09:11:30,190 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: [mail, uid, ...]>
2018-09-05 09:11:30,191 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: mail>
2018-09-05 09:11:30,191 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: uid>
2018-09-05 09:11:30,193 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,193 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2018-09-05 09:11:30,194 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2018-09-05 09:11:30,194 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2018-09-05 09:11:30,194 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,195 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2018-09-05 09:11:30,203 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasTicketGrantingTicketCreatedEvent@64eeb930[ticketGrantingTicket=TGT-**********************************************0jaimUC4eF-cas]>
2018-09-05 09:11:30,205 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(TicketGrantingTicket org.apereo.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket(AuthenticationResult))]>
2018-09-05 09:11:30,207 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: TGT-**********************************************0jaimUC4eF-cas
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,207 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: TGT-**********************************************0jaimUC4eF-cas
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,261 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-**********************************************0jaimUC...@nnn.nnn.nnn.nnn@Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36]>
2018-09-05 09:11:30,264 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Encrypting via [A128CBC-HS256]>
2018-09-05 09:11:30,264 DEBUG [org.apereo.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Added cookie with name [TGC] and value [eyJh****H8nw]>
2018-09-05 09:11:30,273 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2018-09-05 09:11:30,273 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [userfoo] for inclusion in result>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{uid=userfoo, LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ...}] for inclusion in this result for principal [userfoo]>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [samlAuthenticationStatementAuthMethod] -> [urn:oasis:names:tc:SAML:1.0:am:password]>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2018-09-05 09:11:30,279 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [userfoo] as the primary principal>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [userfoo]>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{samlAuthenticationStatementAuthMethod=urn:oasis:names:tc:SAML:1.0:am:password, authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2018-09-05 09:11:30,280 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2018-09-05T09:11:30.280-10:00[Pacific/Johnston]]>
2018-09-05 09:11:30,281 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@db3e8f9f and service http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas>
2018-09-05 09:11:30,283 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for userfoo>
2018-09-05 09:11:30,287 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}]>
2018-09-05 09:11:30,287 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [10] cached attributes for principal [userfoo] that are {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=***...***,ou=People,dc=example,dc=edu, mail=use...@example.edu, ..., uid=userfoo} for userfoo>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for userfoo>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for userfoo>
2018-09-05 09:11:30,290 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2018-09-05 09:11:30,291 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2018-09-05 09:11:30,291 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: [mail, uid, ...]>
2018-09-05 09:11:30,293 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: mail>
2018-09-05 09:11:30,293 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found and added default attribute for release: uid>
2018-09-05 09:11:30,295 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,295 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {mail=use...@example.edu, ..., uid=userfoo}>
2018-09-05 09:11:30,296 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2018-09-05 09:11:30,297 DEBUG [org.apereo.cas.services.RegisteredServiceAccessStrategyUtils] - <Current authentication via ticket TGT-**********************************************0jaimUC4eF-cas allows service http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas to participate in the existing SSO session>
2018-09-05 09:11:30,297 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Looking up service ticket id generator for [org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2018-09-05 09:11:30,297 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Attempting to encode service ticket ST-3-BIFc10BUP5tlytlicB1A-cas>
2018-09-05 09:11:30,298 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Encoded service ticket id ST-3-BIFc10BUP5tlytlicB1A-cas>
2018-09-05 09:11:30,317 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-3-BIFc10BUP5tlytlicB1A-cas] for service [http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas] and principal [userfoo]>
2018-09-05 09:11:30,317 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketGrantedEvent@6c099283[ticketGrantingTicket=TGT-**********************************************0jaimUC4eF-cas,serviceTicket=ST-3-BIFc10BUP5tlytlicB1A-cas]>
2018-09-05 09:11:30,317 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(ServiceTicket org.apereo.cas.CentralAuthenticationServiceImpl.grantServiceTicket(String,Service,AuthenticationResult))]>
2018-09-05 09:11:30,318 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: userfoo
WHAT: ST-3-BIFc10BUP5tlytlicB1A-cas for http://cas.example.edu/cas/oauth2.0/callbackAuthorize?client_name=CasOAuthClient&client_id=OAuth_test&redirect_uri=http://localhost:8080/login/cas
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Wed Sep 05 09:11:30 HST 2018
CLIENT IP ADDRESS: nnn.nnn.nnn.nnn
SERVER IP ADDRESS: mmm.mmm.mmm.mmm
=============================================================
>
2018-09-05 09:11:30,324 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Decrypting value...>
2018-09-05 09:11:30,325 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Decoded cookie value is [TGT-**********************************************0jaimUC...@nnn.nnn.nnn.nnn@Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36]>
2018-09-05 09:11:30,432 DEBUG [org.apereo.cas.web.FlowExecutionExceptionResolver] - <Ignoring the received exception due to a type mismatch>
org.pac4j.core.exception.TechnicalException: cannot validate CAS ticket: ST-3-BIFc10BUP5tlytlicB1A-cas
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:76) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:26) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClientV2.retrieveCredentials(IndirectClientV2.java:49) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClient.getCredentials(IndirectClient.java:106) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.engine.DefaultCallbackLogic.perform(DefaultCallbackLogic.java:77) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.springframework.web.CallbackController.callback(CallbackController.java:53) ~[spring-webmvc-pac4j-1.1.4.jar:?]
at org.apereo.cas.support.oauth.web.OAuth20CallbackAuthorizeController.handleRequestInternal(OAuth20CallbackAuthorizeController.java:45) ~[cas-server-support-oauth-5.0.10.jar:5.0.10]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_172]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_172]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:220) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) ~[servlet-api.jar:?]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) ~[servlet-api.jar:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.web.support.CurrentCredentialsAndAuthenticationClearingFilter.doFilter(CurrentCredentialsAndAuthenticationClearingFilter.java:28) ~[cas-server-core-web-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.RequestParameterPolicyEnforcementFilter.doFilter(RequestParameterPolicyEnforcementFilter.java:261) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.ResponseHeadersEnforcementFilter.doFilter(ResponseHeadersEnforcementFilter.java:238) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:105) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.logging.web.ThreadContextMDCServletFilter.doFilter(ThreadContextMDCServletFilter.java:90) ~[cas-server-core-logging-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:107) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:61) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:92) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:110) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:64) ~[inspektr-common-1.7.GA.jar:1.7.GA]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) ~[log4j-web-2.6.2.jar:2.6.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[catalina.jar:8.5.31]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:613) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) ~[catalina.jar:8.5.31]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) ~[catalina.jar:8.5.31]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-coyote.jar:8.5.31]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_172]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_172]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:8.5.31]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
Caused by: org.jasig.cas.client.validation.TicketValidationException: No principal was found in the response from the CAS server.
at org.jasig.cas.client.validation.Cas20ServiceTicketValidator.parseResponseFromServer(Cas20ServiceTicketValidator.java:98) ~[cas-client-core-3.4.1.jar:3.4.1]
at org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:201) ~[cas-client-core-3.4.1.jar:3.4.1]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:60) ~[pac4j-cas-1.9.7.jar:?]
... 94 more
2018-09-05 09:11:30,432 ERROR [org.springframework.boot.web.support.ErrorPageFilter] - <Forwarding to error page from request [/oauth2.0/callbackAuthorize] due to exception [cannot validate CAS ticket: ST-3-BIFc10BUP5tlytlicB1A-cas]>
org.pac4j.core.exception.TechnicalException: cannot validate CAS ticket: ST-3-BIFc10BUP5tlytlicB1A-cas
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:76) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:26) ~[pac4j-cas-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClientV2.retrieveCredentials(IndirectClientV2.java:49) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.client.IndirectClient.getCredentials(IndirectClient.java:106) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.core.engine.DefaultCallbackLogic.perform(DefaultCallbackLogic.java:77) ~[pac4j-core-1.9.7.jar:?]
at org.pac4j.springframework.web.CallbackController.callback(CallbackController.java:53) ~[spring-webmvc-pac4j-1.1.4.jar:?]
at org.apereo.cas.support.oauth.web.OAuth20CallbackAuthorizeController.handleRequestInternal(OAuth20CallbackAuthorizeController.java:45) ~[cas-server-support-oauth-5.0.10.jar:5.0.10]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_172]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_172]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_172]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_172]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:220) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) ~[servlet-api.jar:?]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) ~[servlet-api.jar:?]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.web.support.CurrentCredentialsAndAuthenticationClearingFilter.doFilter(CurrentCredentialsAndAuthenticationClearingFilter.java:28) ~[cas-server-core-web-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.RequestParameterPolicyEnforcementFilter.doFilter(RequestParameterPolicyEnforcementFilter.java:261) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.security.ResponseHeadersEnforcementFilter.doFilter(ResponseHeadersEnforcementFilter.java:238) ~[cas-server-security-filter-2.0.6.jar:2.0.6]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:105) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.cas.logging.web.ThreadContextMDCServletFilter.doFilter(ThreadContextMDCServletFilter.java:90) ~[cas-server-core-logging-5.0.10.jar:5.0.10]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:107) ~[spring-boot-actuator-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:117) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.access$000(ErrorPageFilter.java:61) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:92) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.3.4.RELEASE.jar:4.3.4.RELEASE]
at org.springframework.boot.web.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:110) ~[spring-boot-1.4.2.RELEASE.jar:1.4.2.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apereo.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:64) ~[inspektr-common-1.7.GA.jar:1.7.GA]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) ~[log4j-web-2.6.2.jar:2.6.2]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[catalina.jar:8.5.31]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:613) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[catalina.jar:8.5.31]
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) ~[catalina.jar:8.5.31]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) ~[catalina.jar:8.5.31]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) ~[catalina.jar:8.5.31]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-coyote.jar:8.5.31]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468) ~[tomcat-coyote.jar:8.5.31]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-coyote.jar:8.5.31]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_172]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_172]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:8.5.31]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
Caused by: org.jasig.cas.client.validation.TicketValidationException: No principal was found in the response from the CAS server.
at org.jasig.cas.client.validation.Cas20ServiceTicketValidator.parseResponseFromServer(Cas20ServiceTicketValidator.java:98) ~[cas-client-core-3.4.1.jar:3.4.1]
at org.jasig.cas.client.validation.AbstractUrlBasedTicketValidator.validate(AbstractUrlBasedTicketValidator.java:201) ~[cas-client-core-3.4.1.jar:3.4.1]
at org.pac4j.cas.credentials.authenticator.CasAuthenticator.validate(CasAuthenticator.java:60) ~[pac4j-cas-1.9.7.jar:?]
... 94 more
Travis Schmidt
Sep 5, 2018, 6:59:14 PM9/5/18
to cas-...@apereo.org
If you are running in case servers in a cluster I think it is required to use some shared session mechanism between the nodes for the current OAuth implementation. This is due to the pac4j reliance on server side session store. This might cause your issue.
--
- Website: https://apereo.github.io/cas
- Gitter Chatroom: https://gitter.im/apereo/cas
- List Guidelines: https://goo.gl/1VRrw7
- Contributions: https://goo.gl/mh7qDG
---
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/20180905202302.bkkwluhdlydke5m7%40combobulate.mgt.hawaii.edu.
Andy Ng
Sep 5, 2018, 9:29:35 PM9/5/18
to CAS Community
Hi Baron,
> ... shared session mechanism ...
I agree with Travis, without shared session some function (e.g. OAuth, pac4j...) of CAS might not work properly.
To verified that shared session might or might not be a problem, try minimize your cluster to only a single node, if that worked, then it will likely be the problem of shared session.
> Debug log
The problem is definitely not in [/oauth2.0/callbackAuthorize], it is in the validation of CAS ticket. Other might have a better idea, I am not too familiar with CAS ticket and how that is validated.
Well if you have a development environment, then it might worth your time to check it out, if all the other methods failed that is.
Cheers!
- Andy
Baron Fujimoto
Sep 5, 2018, 11:10:17 PM9/5/18
to cas-...@apereo.org
The service is defined as a cluster using hazelcast, but I had shut down the other node prior to conducting these tests. Hazelcast still seems to decode tickets and whatnot in this degenerate cluster, but there's only a single node available.
>To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/CAC_RtEY9sr7RPeJEfU7X7kLzAXG1g-pB1FAQhFsxostV1Y6YkA%40mail.gmail.com.
Baron Fujimoto
Sep 7, 2018, 11:45:48 PM9/7/18
to cas-...@apereo.org
Does anyone have suggestions or ideas on how we could troubleshoot this further?
Reply all
Reply to author
Forward
0 new messages