Debug output attached.
--
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 [email protected].
To post to this group, send email to [email protected].
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit
https://groups.google.com/a/apereo.org/d/msgid/cas-user/161f20ec-ee96-471d-aa46-74c2c053d36c%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
:clean
:protected-web-app:clean
:protected-web-app:prepareInplaceWebAppFolder
:protected-web-app:createInplaceWebAppFolder UP-TO-DATE
:protected-web-app:compileJava
:protected-web-app:processResources UP-TO-DATE
:protected-web-app:classes
:protected-web-app:prepareInplaceWebAppClasses
:protected-web-app:prepareInplaceWebApp
:farmBeforeIntegrationTest
2016-07-05 14:27:20,928 DEBUG [org.jasig.cas.CasEnvironmentContextListener] -
<[CasEnvironmentContextListener] initialized...>
14:27:21 INFO No Spring WebApplicationInitializer types detected on classpath
2016-07-05 14:27:21,140 INFO [org.jasig.cas.CasEnvironmentContextListener] - <
******************** Welcome to CAS *******************
CAS Version: 4.2.2
Build Date/Time: 2016-05-20T12:21:38.000-04:00
Java Home: /Library/Java/JavaVirtualMachines/jdk1.8.0_60.jdk/Contents/Home/jre
Java Vendor: Oracle Corporation
Java Version: 1.8.0_60
OS Architecture: x86_64
OS Name: Mac OS X
OS Version: 10.11.5
*******************************************************
>
14:27:21 INFO Initializing Spring root WebApplicationContext
2016-07-05 14:27:23,222 DEBUG
[org.jasig.cas.services.JsonServiceRegistryConfigWatcher] - <Created service
registry watcher for events of type [ENTRY_CREATE, ENTRY_DELETE, ENTRY_MODIFY]>
2016-07-05 14:27:23,225 DEBUG
[org.jasig.cas.services.JsonServiceRegistryConfigWatcher] - <Watching service
registry directory at
/Users/william.crowell/Documents/workspace4/cas-functional-tests/etc/services>
2016-07-05 14:27:23,225 DEBUG [org.jasig.cas.services.JsonServiceRegistryDao] -
<Started service registry watcher thread>
2016-07-05 14:27:23,348 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service https://localhost:8443/cas-services.*>
2016-07-05 14:27:23,348 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service https://localhost:8443/protected-web-app.*>
2016-07-05 14:27:23,348 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service http://localhost:8080/protected-web-app.*>
2016-07-05 14:27:23,348 INFO
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 3 services from
JsonServiceRegistryDao.>
2016-07-05 14:27:23,353 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Found CAS servlet
application context for service management>
2016-07-05 14:27:23,353 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Preparing to schedule
reloader job>
2016-07-05 14:27:23,357 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Scheduling
org.jasig.cas.services.DefaultServicesManagerImpl job>
2016-07-05 14:27:23,357 INFO
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Services manager will
reload service definitions every 60 seconds>
2016-07-05 14:27:23,534 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <DefaultTicketRegistry
is used as the active current ticket registry>
2016-07-05 14:27:23,534 INFO
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Preparing to schedule
job to clean up after tickets...>
2016-07-05 14:27:23,534 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Scheduling
DefaultTicketRegistry job>
2016-07-05 14:27:23,534 INFO
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <DefaultTicketRegistry
will clean tickets every 2 minutes>
2016-07-05 14:27:23,812 DEBUG [org.jasig.cas.CasEnvironmentContextListener] -
<[CasEnvironmentContextListener] initialized...>
2016-07-05 14:27:23,991 DEBUG [org.jasig.cas.util.TGCCipherExecutor] -
<Initialized cipher encryption sequence via [A128CBC-HS256]>
2016-07-05 14:27:23,999 WARN [org.jasig.cas.util.WebflowCipherExecutor] -
<Secret key for signing is not defined. CAS will attempt to auto-generate the
signing key>
2016-07-05 14:27:24,000 WARN [org.jasig.cas.util.WebflowCipherExecutor] -
<Generated signing key
nSB4czbhrqwWcp0OaVOPyBTAYjuI6uNalWizlVMnwtPowTMUsfCvfKwaIuZGrcFkMuY3C53uxUub06CVC3G6qA
of size 512. The generated key MUST be added to CAS settings.>
2016-07-05 14:27:24,000 WARN [org.jasig.cas.util.WebflowCipherExecutor] - <No
encryption key is defined. CAS will attempt to auto-generate keys>
2016-07-05 14:27:24,001 WARN [org.jasig.cas.util.WebflowCipherExecutor] -
<Generated encryption key CUTZhTgKTmPHnEnK of size 16. The generated key MUST
be added to CAS settings.>
2016-07-05 14:27:24,064 DEBUG
[org.jasig.cas.web.support.DefaultCasCookieValueManager] - <Using cipher [class
org.jasig.cas.util.TGCCipherExecutor to encrypt and decode the cookie>
2016-07-05 14:27:24,156 DEBUG
[org.jasig.cas.web.support.InMemoryThrottledSubmissionByIpAddressAndUsernameHandlerInterceptorAdapter]
- <Found CAS servlet application context>
2016-07-05 14:27:24,157 DEBUG
[org.jasig.cas.web.support.InMemoryThrottledSubmissionByIpAddressAndUsernameHandlerInterceptorAdapter]
- <InMemoryThrottledSubmissionByIpAddressAndUsernameHandlerInterceptorAdapter
is used as the active authentication throttle>
2016-07-05 14:27:24,170 DEBUG
[org.jasig.cas.web.support.InMemoryThrottledSubmissionByIpAddressHandlerInterceptorAdapter]
- <Found CAS servlet application context>
2016-07-05 14:27:24,170 DEBUG
[org.jasig.cas.web.support.InMemoryThrottledSubmissionByIpAddressHandlerInterceptorAdapter]
- <InMemoryThrottledSubmissionByIpAddressHandlerInterceptorAdapter is used as
the active authentication throttle>
2016-07-05 14:27:24,187 DEBUG
[org.jasig.cas.web.support.InspektrThrottledSubmissionByIpAddressAndUsernameHandlerInterceptorAdapter]
- <No data source is defined for inspektrIpAddressUsernameThrottle. Ignoring
the construction of JDBC template>
2016-07-05 14:27:24,299 DEBUG [org.jasig.cas.web.view.Cas30JsonResponseView] -
<Initialized Cas30JsonResponseView>
2016-07-05 14:27:25,391 INFO [org.jasig.cas.CasEnvironmentContextListener] -
<[jetty/9.2.15.v20160210] has loaded the CAS servlet application context: Root
WebApplicationContext: startup date [Tue Jul 05 14:27:21 EDT 2016]; root of
context hierarchy>
14:27:25 INFO Initializing Spring FrameworkServlet 'cas'
14:27:31 INFO No Spring WebApplicationInitializer types detected on classpath
14:27:31 INFO Initializing Spring root WebApplicationContext
2016-07-05 14:27:32,756 DEBUG
[org.jasig.cas.services.JsonServiceRegistryConfigWatcher] - <Created service
registry watcher for events of type [ENTRY_CREATE, ENTRY_DELETE, ENTRY_MODIFY]>
2016-07-05 14:27:32,757 DEBUG
[org.jasig.cas.services.JsonServiceRegistryConfigWatcher] - <Watching service
registry directory at
/Users/william.crowell/Documents/workspace4/cas-functional-tests/etc/services>
2016-07-05 14:27:32,758 DEBUG [org.jasig.cas.services.JsonServiceRegistryDao] -
<Started service registry watcher thread>
2016-07-05 14:27:32,870 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service https://localhost:8443/cas-services.*>
2016-07-05 14:27:32,870 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service https://localhost:8443/protected-web-app.*>
2016-07-05 14:27:32,870 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service http://localhost:8080/protected-web-app.*>
2016-07-05 14:27:32,870 INFO
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 3 services from
JsonServiceRegistryDao.>
2016-07-05 14:27:32,921 DEBUG [org.jasig.cas.CasEnvironmentContextListener] -
<[CasEnvironmentContextListener] initialized...>
2016-07-05 14:27:32,961 INFO [org.jasig.cas.CasEnvironmentContextListener] - <
******************** Welcome to CAS *******************
CAS Version: 4.2.2
Build Date/Time: 2016-05-20T12:21:38.000-04:00
Java Home: /Library/Java/JavaVirtualMachines/jdk1.8.0_60.jdk/Contents/Home/jre
Java Vendor: Oracle Corporation
Java Version: 1.8.0_60
OS Architecture: x86_64
OS Name: Mac OS X
OS Version: 10.11.5
*******************************************************
>
2016-07-05 14:27:33,582 DEBUG [org.jasig.cas.util.TGCCipherExecutor] -
<Initialized cipher encryption sequence via [A128CBC-HS256]>
2016-07-05 14:27:33,589 WARN [org.jasig.cas.util.WebflowCipherExecutor] -
<Secret key for signing is not defined. CAS will attempt to auto-generate the
signing key>
2016-07-05 14:27:33,590 WARN [org.jasig.cas.util.WebflowCipherExecutor] -
<Generated signing key
_aiMP0AjTgRXvnRyBZuu6N1zMXYm9vCZF3fq1mOePJtuEIMeS28zJmuMWGc69FB2KfnApS8Uv-BhS6SRmKP4Zw
of size 512. The generated key MUST be added to CAS settings.>
2016-07-05 14:27:33,590 WARN [org.jasig.cas.util.WebflowCipherExecutor] - <No
encryption key is defined. CAS will attempt to auto-generate keys>
2016-07-05 14:27:33,591 WARN [org.jasig.cas.util.WebflowCipherExecutor] -
<Generated encryption key YvOKHoEPIUBWXiik of size 16. The generated key MUST
be added to CAS settings.>
14:27:34 INFO Initializing Spring FrameworkServlet 'cas-management'
14:27:34 INFO Jetty 9.2.15.v20160210 started and listening on ports 8080, 8443
14:27:34 INFO Central Authentication System (CAS) runs at:
14:27:34 INFO http://localhost:8080/cas
14:27:34 INFO https://localhost:8443/cas
14:27:34 INFO CAS Management runs at:
14:27:34 INFO http://localhost:8080/cas-services
14:27:34 INFO https://localhost:8443/cas-services
14:27:34 INFO protected-web-app runs at:
14:27:34 INFO http://localhost:8080/protected-web-app
14:27:34 INFO https://localhost:8443/protected-web-app
:farmIntegrationTest
:compileJava UP-TO-DATE
:compileGroovy UP-TO-DATE
:processResources UP-TO-DATE
:classes UP-TO-DATE
:war
:assemble
:compileTestJava UP-TO-DATE
:compileTestGroovy
:processTestResources
:testClasses
:test
2016-07-05 14:27:38,266 INFO
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<AcceptUsersAuthenticationHandler successfully authenticated casuser>
2016-07-05 14:27:38,266 DEBUG
[org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] -
<Attempting to resolve a principal...>
2016-07-05 14:27:38,267 DEBUG
[org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] -
<Creating SimplePrincipal for [casuser]>
2016-07-05 14:27:38,267 DEBUG
[org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] -
<Principal id [casuser] could not be found>
2016-07-05 14:27:38,267 DEBUG
[org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver] -
<Retrieved [4] attribute(s) from the repository>
2016-07-05 14:27:38,268 DEBUG
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<org.jasig.cas.authentication.principal.PersonDirectoryPrincipalResolver@6032622
resolved casuser from casuser>
2016-07-05 14:27:38,270 INFO
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<Authenticated casuser with credentials [casuser].>
2016-07-05 14:27:38,270 DEBUG
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute
map for casuser: {uid=uid, eduPersonAffiliation=eduPersonAffiliation,
memberOf=[faculty, staff, org], groupMembership=groupMembership}>
2016-07-05 14:27:38,272 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [AuthenticationTransaction] for audit>
2016-07-05 14:27:38,272 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [UsernamePasswordCredential] for audit>
2016-07-05 14:27:38,273 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: casuser
WHAT: Supplied credentials: [casuser]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:38 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:38,274 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationTransactionManager] -
<Successful authentication; Collecting authentication result
[org.jasig.cas.authentication.ImmutableAuthentication@63c04ac1]>
2016-07-05 14:27:38,274 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationTransactionManager] -
<Transaction ignored since there are no credentials to authenticate>
2016-07-05 14:27:38,274 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Collecting authentication history based on [1] authentication events>
2016-07-05 14:27:38,274 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Evaluating authentication principal [casuser] for inclusion in context>
2016-07-05 14:27:38,274 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
principal attributes [{uid=uid, memberOf=[faculty, staff, org],
groupMembership=groupMembership, eduPersonAffiliation=eduPersonAffiliation}]
for inclusion in context for principal [casuser]>
2016-07-05 14:27:38,275 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
single authentication attribute [authenticationMethod] ->
[AcceptUsersAuthenticationHandler]>
2016-07-05 14:27:38,275 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
single authentication attribute [successfulAuthenticationHandlers] ->
[[AcceptUsersAuthenticationHandler]]>
2016-07-05 14:27:38,275 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Finalized
authentication attributes
[{authenticationMethod=AcceptUsersAuthenticationHandler,
successfulAuthenticationHandlers=[AcceptUsersAuthenticationHandler]}] for
inclusion in authentication context>
2016-07-05 14:27:38,276 DEBUG
[org.jasig.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated
[casuser] as the primary principal>
2016-07-05 14:27:38,277 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Determined primary authentication principal to be [casuser]>
2016-07-05 14:27:38,277 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
authentication attributes for this context are
[{authenticationMethod=AcceptUsersAuthenticationHandler,
successfulAuthenticationHandlers=[AcceptUsersAuthenticationHandler]}]>
2016-07-05 14:27:38,277 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Authentication context commenced at [2016-07-05T14:27:38.277-04:00]>
2016-07-05 14:27:38,277 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Building
an authentication context for authentication
org.jasig.cas.authentication.ImmutableAuthentication@663a6c6e and service null>
2016-07-05 14:27:38,284 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
to registry.>
2016-07-05 14:27:38,285 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Publishing
org.jasig.cas.support.events.CasTicketGrantingTicketCreatedEvent@6730a9cd[ticketGrantingTicket=TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:38,285 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [DefaultAuthenticationContext] for audit>
2016-07-05 14:27:38,286 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: audit:unknown
WHAT:
TGT-**********************************************mQFnCLcEOn-cas01.example.org
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:38 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:38,337 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:38,337 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
found in registry.>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Collecting authentication history based on [1] authentication events>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Evaluating authentication principal [casuser] for inclusion in context>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
principal attributes [{uid=uid, memberOf=[faculty, staff, org],
groupMembership=groupMembership, eduPersonAffiliation=eduPersonAffiliation}]
for inclusion in context for principal [casuser]>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
single authentication attribute [authenticationMethod] ->
[AcceptUsersAuthenticationHandler]>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
single authentication attribute [successfulAuthenticationHandlers] ->
[[AcceptUsersAuthenticationHandler]]>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Finalized
authentication attributes
[{authenticationMethod=AcceptUsersAuthenticationHandler,
successfulAuthenticationHandlers=[AcceptUsersAuthenticationHandler]}] for
inclusion in authentication context>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated
[casuser] as the primary principal>
2016-07-05 14:27:38,338 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Determined primary authentication principal to be [casuser]>
2016-07-05 14:27:38,339 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
authentication attributes for this context are
[{authenticationMethod=AcceptUsersAuthenticationHandler,
successfulAuthenticationHandlers=[AcceptUsersAuthenticationHandler]}]>
2016-07-05 14:27:38,339 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Authentication context commenced at [2016-07-05T14:27:38.339-04:00]>
2016-07-05 14:27:38,339 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Building
an authentication context for authentication
org.jasig.cas.authentication.ImmutableAuthentication@63091934 and service
https://localhost:8443/protected-web-app/>
2016-07-05 14:27:38,342 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:38,342 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
found in registry.>
2016-07-05 14:27:38,347 DEBUG [org.jasig.cas.util.RegexUtils] - <Pattern
https://localhost:8443/protected-web-app.* is a valid regex.>
2016-07-05 14:27:38,352 DEBUG
[org.jasig.cas.authentication.principal.DefaultPrincipalAttributesRepository] -
<DefaultPrincipalAttributesRepository will return the collection of attributes
directly associated with the principal object>
2016-07-05 14:27:38,352 DEBUG
[org.jasig.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository]
- <Found [4] cached attributes for principal [casuser]>
2016-07-05 14:27:38,352 DEBUG
[org.jasig.cas.services.DefaultRegisteredServiceAccessStrategy] - <No required
attributes are specified>
2016-07-05 14:27:38,352 DEBUG
[org.jasig.cas.ticket.DefaultServiceTicketFactory] - <Looking up service ticket
id generator for
[org.jasig.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2016-07-05 14:27:38,354 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] to registry.>
2016-07-05 14:27:38,354 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] -
<Granted ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] for service
[https://localhost:8443/protected-web-app/] and principal [casuser]>
2016-07-05 14:27:38,356 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Publishing
org.jasig.cas.support.events.CasServiceTicketGrantedEvent@7e7f268e[ticketGrantingTicket=TGT-**********************************************mQFnCLcEOn-cas01.example.org,serviceTicket=ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,356 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [String] for audit>
2016-07-05 14:27:38,357 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:38,357 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
found in registry.>
2016-07-05 14:27:38,360 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: casuser
WHAT: ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org for
https://localhost:8443/protected-web-app/
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:38 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:38,363 DEBUG [org.jasig.cas.util.CasSpringBeanJobFactory] -
<Created job
org.jasig.cas.services.DefaultServicesManagerImpl$ServiceRegistryReloaderJob@59f67532
for bundle org.quartz.spi.TriggerFiredBundle@6c6f6e9f>
2016-07-05 14:27:38,366 DEBUG [org.jasig.cas.util.CasSpringBeanJobFactory] -
<Autowired job per the application context>
2016-07-05 14:27:38,368 INFO
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Reloading registered
services.>
2016-07-05 14:27:38,373 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service https://localhost:8443/cas-services.*>
2016-07-05 14:27:38,374 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service https://localhost:8443/protected-web-app.*>
2016-07-05 14:27:38,374 DEBUG
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Adding registered
service http://localhost:8080/protected-web-app.*>
2016-07-05 14:27:38,374 INFO
[org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 3 services from
JsonServiceRegistryDao.>
2016-07-05 14:27:38,381 DEBUG
[org.jasig.cas.web.support.DefaultArgumentExtractor] - <Created
https://localhost:8443/protected-web-app/ based on
org.jasig.cas.authentication.principal.WebApplicationServiceFactory@6f6e84fc>
2016-07-05 14:27:38,381 DEBUG
[org.jasig.cas.web.support.DefaultArgumentExtractor] - <Extractor generated
service for: https://localhost:8443/protected-web-app/>
2016-07-05 14:27:38,383 DEBUG [org.jasig.cas.util.RegexUtils] - <Pattern
https://localhost:8443/protected-web-app.* is a valid regex.>
2016-07-05 14:27:38,386 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,386 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] found in registry.>
2016-07-05 14:27:38,389 DEBUG
[org.jasig.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler]
- <Attempting to authenticate
https://localhost:8443/protected-web-app/proxyUrl>
2016-07-05 14:27:38,421 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Connecting
socket to localhost/127.0.0.1:8443 with timeout 5000>
2016-07-05 14:27:38,424 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Enabled
protocols: [TLSv1, TLSv1.1, TLSv1.2]>
2016-07-05 14:27:38,424 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Enabled cipher
suites:[TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]>
2016-07-05 14:27:38,424 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Starting
handshake>
2016-07-05 14:27:38,448 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Secure session
established>
2016-07-05 14:27:38,449 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < negotiated
protocol: TLSv1.2>
2016-07-05 14:27:38,449 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < negotiated
cipher suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256>
2016-07-05 14:27:38,449 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < peer
principal: CN=localhost, OU=Tech, O=TSTi, L=Redmond, ST=WA, C=US>
2016-07-05 14:27:38,450 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < issuer
principal: CN=localhost, OU=Tech, O=TSTi, L=Redmond, ST=WA, C=US>
2016-07-05 14:27:38,462 DEBUG [org.jasig.cas.util.http.SimpleHttpClient] -
<Response code from server matched 200.>
2016-07-05 14:27:38,462 INFO
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<HttpBasedServiceCredentialsAuthenticationHandler successfully authenticated
https://localhost:8443/protected-web-app/proxyUrl>
2016-07-05 14:27:38,463 DEBUG
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<org.jasig.cas.authentication.principal.BasicPrincipalResolver@5d77be8e
resolved https://localhost:8443/protected-web-app/proxyUrl from
https://localhost:8443/protected-web-app/proxyUrl>
2016-07-05 14:27:38,463 INFO
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] -
<Authenticated https://localhost:8443/protected-web-app/proxyUrl with
credentials [https://localhost:8443/protected-web-app/proxyUrl].>
2016-07-05 14:27:38,463 DEBUG
[org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute
map for https://localhost:8443/protected-web-app/proxyUrl: {}>
2016-07-05 14:27:38,463 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [AuthenticationTransaction] for audit>
2016-07-05 14:27:38,463 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [HttpBasedServiceCredential] for audit>
2016-07-05 14:27:38,464 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: https://localhost:8443/protected-web-app/proxyUrl
WHAT: Supplied credentials: [https://localhost:8443/protected-web-app/proxyUrl]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:38 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:38,464 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationTransactionManager] -
<Successful authentication; Collecting authentication result
[org.jasig.cas.authentication.ImmutableAuthentication@dd52d5dd]>
2016-07-05 14:27:38,464 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationTransactionManager] -
<Transaction ignored since there are no credentials to authenticate>
2016-07-05 14:27:38,464 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Collecting authentication history based on [1] authentication events>
2016-07-05 14:27:38,464 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Evaluating authentication principal
[https://localhost:8443/protected-web-app/proxyUrl] for inclusion in context>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
principal attributes [{}] for inclusion in context for principal
[https://localhost:8443/protected-web-app/proxyUrl]>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
single authentication attribute [authenticationMethod] ->
[HttpBasedServiceCredentialsAuthenticationHandler]>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
single authentication attribute [successfulAuthenticationHandlers] ->
[[HttpBasedServiceCredentialsAuthenticationHandler]]>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Finalized
authentication attributes
[{authenticationMethod=HttpBasedServiceCredentialsAuthenticationHandler,
successfulAuthenticationHandlers=[HttpBasedServiceCredentialsAuthenticationHandler]}]
for inclusion in authentication context>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated
[https://localhost:8443/protected-web-app/proxyUrl] as the primary principal>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Determined primary authentication principal to be
[https://localhost:8443/protected-web-app/proxyUrl]>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Collected
authentication attributes for this context are
[{authenticationMethod=HttpBasedServiceCredentialsAuthenticationHandler,
successfulAuthenticationHandlers=[HttpBasedServiceCredentialsAuthenticationHandler]}]>
2016-07-05 14:27:38,465 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] -
<Authentication context commenced at [2016-07-05T14:27:38.465-04:00]>
2016-07-05 14:27:38,466 DEBUG
[org.jasig.cas.authentication.DefaultAuthenticationContextBuilder] - <Building
an authentication context for authentication
org.jasig.cas.authentication.ImmutableAuthentication@dc9ba450 and service
https://localhost:8443/protected-web-app/>
2016-07-05 14:27:38,467 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,467 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] found in registry.>
2016-07-05 14:27:38,470 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Generated proxy granting ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]
based off of [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,470 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]
to registry.>
2016-07-05 14:27:38,471 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Publishing
org.jasig.cas.support.events.CasProxyGrantingTicketCreatedEvent@6b7730b6[ticketGrantingTicket=PGT-**********************************************TXMRcMHpec-cas01.example.org]>
2016-07-05 14:27:38,471 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [String] for audit>
2016-07-05 14:27:38,471 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,471 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] found in registry.>
2016-07-05 14:27:38,471 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: casuser
WHAT:
PGT-**********************************************TXMRcMHpec-cas01.example.org
ACTION: PROXY_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:38 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:38,472 DEBUG [org.jasig.cas.web.ServiceValidateController] -
<Generated proxy-granting ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]
off of service ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] and
credential [https://localhost:8443/protected-web-app/proxyUrl]>
2016-07-05 14:27:38,474 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,474 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] found in registry.>
2016-07-05 14:27:38,475 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Attribute policy
[org.jasig.cas.services.ReturnAllAttributeReleasePolicy@34574a67[attributeFilter=<null>,principalAttributesRepository=org.jasig.cas.authentication.principal.DefaultPrincipalAttributesRepository@302e9d76[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false]]
is associated with service [id=52497044623302,name=CAS Example Protected Web
Application via TLS,description=Services Management Web
Application,serviceId=https://localhost:8443/protected-web-app.*,usernameAttributeProvider=org.jasig.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=1,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.jasig.cas.services.ReturnAllAttributeReleasePolicy@34574a67[attributeFilter=<null>,principalAttributesRepository=org.jasig.cas.authentication.principal.DefaultPrincipalAttributesRepository@302e9d76[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false],accessStrategy=org.jasig.cas.services.DefaultRegisteredServiceAccessStrategy@4cf6172f[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false],publicKey=<null>,proxyPolicy=org.jasig.cas.services.RegexMatchingRegisteredServiceProxyPolicy@614a61c3[^https?://.*],logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},<null>]>
2016-07-05 14:27:38,475 DEBUG
[org.jasig.cas.authentication.principal.DefaultPrincipalAttributesRepository] -
<DefaultPrincipalAttributesRepository will return the collection of attributes
directly associated with the principal object>
2016-07-05 14:27:38,475 DEBUG
[org.jasig.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository]
- <Found [4] cached attributes for principal [casuser]>
2016-07-05 14:27:38,476 DEBUG
[org.jasig.cas.services.DefaultRegisteredServiceUsernameProvider] - <Returning
the default principal id [casuser] for username.>
2016-07-05 14:27:38,479 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Publishing
org.jasig.cas.support.events.CasServiceTicketValidatedEvent@58c6ca5f[assertion=org.jasig.cas.authentication.ImmutableAuthentication@663a6c6e:https://localhost:8443/protected-web-app/,serviceTicket=ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,479 DEBUG
[org.jasig.cas.ticket.support.MultiTimeUseOrTimeoutExpirationPolicy] - <Ticket
usage count 1 is greater than or equal to 1>
2016-07-05 14:27:38,479 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,479 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] found in registry.>
2016-07-05 14:27:38,479 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket
[ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] from the registry.>
2016-07-05 14:27:38,480 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [String] for audit>
2016-07-05 14:27:38,480 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org]>
2016-07-05 14:27:38,480 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] by type [Ticket] cannot
be found in the ticket registry.>
2016-07-05 14:27:38,483 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Could not
locate ticket [ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org] in the registry>
2016-07-05 14:27:38,484 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: audit:unknown
WHAT: ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org
ACTION: SERVICE_TICKET_VALIDATED
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:38 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:38,494 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Connecting
socket to localhost/127.0.0.1:8443 with timeout 5000>
2016-07-05 14:27:38,495 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Enabled
protocols: [TLSv1, TLSv1.1, TLSv1.2]>
2016-07-05 14:27:38,495 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Enabled cipher
suites:[TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]>
2016-07-05 14:27:38,495 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Starting
handshake>
2016-07-05 14:27:38,500 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Secure session
established>
2016-07-05 14:27:38,500 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < negotiated
protocol: TLSv1.2>
2016-07-05 14:27:38,500 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < negotiated
cipher suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256>
2016-07-05 14:27:38,500 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < peer
principal: CN=localhost, OU=Tech, O=TSTi, L=Redmond, ST=WA, C=US>
2016-07-05 14:27:38,500 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < issuer
principal: CN=localhost, OU=Tech, O=TSTi, L=Redmond, ST=WA, C=US>
2016-07-05 14:27:38,503 DEBUG [org.jasig.cas.util.http.SimpleHttpClient] -
<Response code from server matched 200.>
2016-07-05 14:27:38,504 DEBUG
[org.jasig.cas.ticket.proxy.support.Cas20ProxyHandler] - <Sent ProxyIou of
PGTIOU-*************************************************c2QhQd9b6J-cas01.example.org
for service: https://localhost:8443/protected-web-app/proxyUrl>
2016-07-05 14:27:38,504 DEBUG [org.jasig.cas.web.ServiceValidateController] -
<Successfully validated service ticket
ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org for service
[https://localhost:8443/protected-web-app/]>
2016-07-05 14:27:38,511 DEBUG
[org.jasig.cas.web.view.Cas20ResponseView$Success] - <Preparing the output
model to render view...>
2016-07-05 14:27:39,243 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Removing ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
from registry...>
2016-07-05 14:27:39,243 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:39,243 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
found in registry.>
2016-07-05 14:27:39,244 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Ticket found. Processing logout requests and then deleting the ticket...>
2016-07-05 14:27:39,258 DEBUG
[org.jasig.cas.logout.SamlCompliantLogoutMessageCreator] - <Generated logout
message: [<samlp:LogoutRequest
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"
ID="LR-1-iQ2bJ65sSmtfbU2datZhf6YUadyRRLbY2wS" Version="2.0"
IssueInstant="2016-07-05T14:27:39Z"><saml:NameID
xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">@NOT_USED@</saml:NameID><samlp:SessionIndex>ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org</samlp:SessionIndex></samlp:LogoutRequest>]>
2016-07-05 14:27:39,259 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] -
<Sending logout request for: [https://localhost:8443/protected-web-app/]>
2016-07-05 14:27:39,260 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] -
<Prepared logout message to send is
[org.jasig.cas.logout.LogoutManagerImpl$LogoutHttpMessage@1bbb913e[url=https://localhost:8443/protected-web-app/,message=<samlp:LogoutRequest
xmlns:samlp="urn:oasis:names:tc:SAML:2.0:protocol"
ID="LR-1-iQ2bJ65sSmtfbU2datZhf6YUadyRRLbY2wS" Version="2.0"
IssueInstant="2016-07-05T14:27:39Z"><saml:NameID
xmlns:saml="urn:oasis:names:tc:SAML:2.0:assertion">@NOT_USED@</saml:NameID><samlp:SessionIndex>ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org</samlp:SessionIndex></samlp:LogoutRequest>,asynchronous=true,contentType=application/x-www-form-urlencoded]]>
2016-07-05 14:27:39,264 DEBUG [org.jasig.cas.logout.LogoutManagerImpl] -
<Captured logout request
[org.jasig.cas.logout.DefaultLogoutRequest@1c0cb23b[ticketId=ST-1-LcgqUXO2jH4z3A9YI6eu-cas01.example.org,service=https://localhost:8443/protected-web-app/,status=SUCCESS]]>
2016-07-05 14:27:39,264 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:39,264 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
found in registry.>
2016-07-05 14:27:39,264 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Removing children of
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
from the registry.>
2016-07-05 14:27:39,264 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
from the registry.>
2016-07-05 14:27:39,265 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Connecting
socket to localhost/127.0.0.1:8443 with timeout 5000>
2016-07-05 14:27:39,266 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Publishing
org.jasig.cas.support.events.CasTicketGrantingTicketDestroyedEvent@379577d0[ticketGrantingTicket=TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:39,266 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [String] for audit>
2016-07-05 14:27:39,266 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]>
2016-07-05 14:27:39,266 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
by type [Ticket] cannot be found in the ticket registry.>
2016-07-05 14:27:39,266 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Enabled
protocols: [TLSv1, TLSv1.1, TLSv1.2]>
2016-07-05 14:27:39,266 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Enabled cipher
suites:[TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256,
TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256,
TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,
TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,
TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA,
TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256,
TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256,
TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256,
TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,
TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]>
2016-07-05 14:27:39,266 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Starting
handshake>
2016-07-05 14:27:39,268 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Could not
locate ticket
[TGT-**********************************************mQFnCLcEOn-cas01.example.org]
in the registry>
2016-07-05 14:27:39,268 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: audit:unknown
WHAT:
TGT-**********************************************mQFnCLcEOn-cas01.example.org
ACTION: TICKET_GRANTING_TICKET_DESTROYED
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:39 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:39,270 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - <Secure session
established>
2016-07-05 14:27:39,270 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < negotiated
protocol: TLSv1.2>
2016-07-05 14:27:39,270 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < negotiated
cipher suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256>
2016-07-05 14:27:39,270 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < peer
principal: CN=localhost, OU=Tech, O=TSTi, L=Redmond, ST=WA, C=US>
2016-07-05 14:27:39,270 DEBUG
[org.jasig.cas.authentication.FileTrustStoreSslSocketFactory] - < issuer
principal: CN=localhost, OU=Tech, O=TSTi, L=Redmond, ST=WA, C=US>
2016-07-05 14:27:39,276 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]>
2016-07-05 14:27:39,276 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]
found in registry.>
2016-07-05 14:27:39,279 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <TGT-TGT is proxied by [https://localhost:8443/protected-web-app/]. Locating
proxy service in registry...>
2016-07-05 14:27:39,281 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Located proxying service [id=52497044623302,name=CAS Example Protected Web
Application via TLS,description=Services Management Web
Application,serviceId=https://localhost:8443/protected-web-app.*,usernameAttributeProvider=org.jasig.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=1,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.jasig.cas.services.ReturnAllAttributeReleasePolicy@34574a67[attributeFilter=<null>,principalAttributesRepository=org.jasig.cas.authentication.principal.DefaultPrincipalAttributesRepository@302e9d76[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false],accessStrategy=org.jasig.cas.services.DefaultRegisteredServiceAccessStrategy@4cf6172f[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false],publicKey=<null>,proxyPolicy=org.jasig.cas.services.RegexMatchingRegisteredServiceProxyPolicy@614a61c3[^https?://.*],logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},<null>]
in the service registry>
2016-07-05 14:27:39,282 DEBUG
[org.jasig.cas.authentication.principal.DefaultPrincipalAttributesRepository] -
<DefaultPrincipalAttributesRepository will return the collection of attributes
directly associated with the principal object>
2016-07-05 14:27:39,282 DEBUG
[org.jasig.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository]
- <Found [4] cached attributes for principal [casuser]>
2016-07-05 14:27:39,282 DEBUG
[org.jasig.cas.services.DefaultRegisteredServiceAccessStrategy] - <No required
attributes are specified>
2016-07-05 14:27:39,282 DEBUG [org.jasig.cas.ticket.DefaultProxyTicketFactory]
- <Looking up service ticket id generator for
[org.jasig.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2016-07-05 14:27:39,283 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket
[PT-2-VfTPNOaeAzsjj3bOtXnX-cas01.example.org] to registry.>
2016-07-05 14:27:39,284 INFO [org.jasig.cas.CentralAuthenticationServiceImpl] -
<Granted ticket [PT-2-VfTPNOaeAzsjj3bOtXnX-cas01.example.org] for service
[https://localhost:8443/protected-web-app/] for user [casuser]>
2016-07-05 14:27:39,286 DEBUG [org.jasig.cas.CentralAuthenticationServiceImpl]
- <Publishing
org.jasig.cas.support.events.CasProxyTicketGrantedEvent@338e8849[proxyGrantingTicket=PGT-**********************************************TXMRcMHpec-cas01.example.org,proxyTicket=PT-2-VfTPNOaeAzsjj3bOtXnX-cas01.example.org]>
2016-07-05 14:27:39,286 DEBUG
[org.jasig.cas.audit.spi.TicketOrCredentialPrincipalResolver] - <Resolving
argument [String] for audit>
2016-07-05 14:27:39,286 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Attempting to retrieve
ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]>
2016-07-05 14:27:39,286 DEBUG
[org.jasig.cas.ticket.registry.DefaultTicketRegistry] - <Ticket
[PGT-**********************************************TXMRcMHpec-cas01.example.org]
found in registry.>
2016-07-05 14:27:39,287 INFO
[org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail
record BEGIN
=============================================================
WHO: https://localhost:8443/protected-web-app/proxyUrl
WHAT: PT-2-VfTPNOaeAzsjj3bOtXnX-cas01.example.org for
https://localhost:8443/protected-web-app/
ACTION: PROXY_TICKET_CREATED
APPLICATION: CAS
WHEN: Tue Jul 05 14:27:39 EDT 2016
CLIENT IP ADDRESS: 127.0.0.1
SERVER IP ADDRESS: 127.0.0.1
=============================================================
>
2016-07-05 14:27:40,266 DEBUG
[org.jasig.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Removed
cookie with name [TGC]>
2016-07-05 14:27:40,266 DEBUG
[org.jasig.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie
with name [CASPRIVACY]>
2016-07-05 14:27:40,272 DEBUG [org.jasig.cas.util.RegexUtils] - <Pattern
http://localhost:8080/protected-web-app.* is a valid regex.>
2016-07-05 14:27:40,272 DEBUG [org.jasig.cas.util.RegexUtils] - <Pattern
https://localhost:8443/cas-services.* is a valid regex.>
2016-07-05 14:27:40,273 DEBUG
[org.jasig.cas.services.web.RegisteredServiceThemeBasedViewResolver] - <View
resolved: /WEB-INF/view/jsp/default/ui/casLogoutView.jsp>
2016-07-05 14:27:40,480 DEBUG
[org.jasig.cas.web.view.CasReloadableMessageBundle] - <No properties file found
for [classpath:custom_messages_en] - neither plain properties nor XML>
2016-07-05 14:27:40,481 DEBUG
[org.jasig.cas.web.view.CasReloadableMessageBundle] - <No properties file found
for [classpath:custom_messages] - neither plain properties nor XML>
2016-07-05 14:27:40,481 DEBUG
[org.jasig.cas.web.view.CasReloadableMessageBundle] - <No properties file found
for [classpath:messages_en] - neither plain properties nor XML>
2016-07-05 14:27:40,481 DEBUG
[org.jasig.cas.web.view.CasReloadableMessageBundle] - <Loading properties
[messages.properties] with encoding 'UTF-8'>
:shutdownHook
:check
:build
:farmAfterIntegrationTest
14:27:40 INFO Destroying Spring FrameworkServlet 'cas-management'
14:27:40 INFO Closing Spring root WebApplicationContext
2016-07-05 14:27:40,577 WARN
[org.jasig.cas.services.JsonServiceRegistryConfigWatcher] - <Directory key is
no longer valid. Quitting watcher service>
14:27:40 INFO Destroying Spring FrameworkServlet 'cas'
14:27:40 INFO Closing Spring root WebApplicationContext
2016-07-05 14:27:40,598 WARN
[org.jasig.cas.services.JsonServiceRegistryConfigWatcher] - <Directory key is
no longer valid. Quitting watcher service>
Server stopped.
:protected-web-app:farmBeforeIntegrationTest SKIPPED
:protected-web-app:farmIntegrationTest SKIPPED
:protected-web-app:farmAfterIntegrationTest SKIPPED
BUILD SUCCESSFUL
Total time: 59.58 secs
