[cas-user] Setting up CAS 5.0.2 Server and Banner XE 404 cas/samlValidate?

39 views
Skip to first unread message

Rob

unread,
Feb 13, 2017, 11:38:38 AM2/13/17
to cas-...@apereo.org
Hello All, 

My question is, is there another place, to set up additional attributes, other than the JSON service definition, attribute release policy, when using SAML 1.1 response?

I am setting up a CAS 5.0.2 server, I have successfully got it hooked up to our LDAP server and authenticating. I have successfully gotten working with our grails 2.5.5 apps. 

I then configured the service policy to return attributes, specifically: 

  "attributeReleasePolicy" : {
    "@class": "org.apereo.cas.services.ReturnMappedAttributeReleasePolicy",
    "allowedAttributes": {
      "@class": "java.util.TreeMap",
      "xxxPersonUDCID": "UDC_IDENTIFIER",
      "uid": "uid",
      "mail": "mail",
      "eduPersonPrincipalName": "eduPersonPrincipalName",
      "eduPersonAffiliation": "eduPersonAffiliation",
      "employeeID": "employeeID",
      "sn": "sn",
      "givenName": "givenName",
      "xxxPersonIdmRoles": "xxxPersonIdmRoles"
    }

I can see in the logs these attributes are being returned.

When I try to auth via banner XE app, it makes a request to /samlValidate which returns the following error:

Error Message: https://casdevinternal.xxx.edu/cas/samlValidate?TARGET=https%3A%2F%2Fxessdev1.xx.edu%3A8446%2FPRDCStudentFacultyGradeEntry%2Fj_spring_cas_security_check    

So I add the dependency for SAML to my pom:

<dependency>
<groupId>org.apereo.cas</groupId>
<artifactId>cas-server-support-saml</artifactId>
<version>5.0.2</version>
</dependency>

That solves the 404 and now I see in the logs CAS is returning a SAML 1.1 response, but not my additional attributes:

<?xml version="1.0" encoding="UTF-8"?>
<saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" InResponseTo="xxx.xxx.edu" IssueInstant="2017-02-10T22:12:53.558Z" MajorVersion="1" MinorVersion="1" ResponseID="_baa0795a4ed62b994dd3839427602a20">
<saml1p:Status>
<saml1p:StatusCode Value="saml1p:Success"/>
</saml1p:Status>
<saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_fb1332132e4c49e4cced0e8458f224d7" IssueInstant="2017-02-10T22:12:53.558Z" Issuer="localhost" MajorVersion="1" MinorVersion="1">
<saml1:Conditions NotBefore="2017-02-10T22:12:53.558Z" NotOnOrAfter="2017-02-10T22:13:23.558Z">
<saml1:AudienceRestrictionCondition>
</saml1:AudienceRestrictionCondition>
</saml1:Conditions>
<saml1:AuthenticationStatement AuthenticationInstant="2017-02-10T22:12:53.380Z" AuthenticationMethod="urn:oasis:names:tc:SAML:1.0:am:password">
<saml1:Subject>
<saml1:NameIdentifier>edelmand</saml1:NameIdentifier>
<saml1:SubjectConfirmation>
<saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:artifact</saml1:ConfirmationMethod>
</saml1:SubjectConfirmation>
</saml1:Subject>
</saml1:AuthenticationStatement>
<saml1:AttributeStatement>
<saml1:Subject>
<saml1:NameIdentifier>joesmith</saml1:NameIdentifier>
<saml1:SubjectConfirmation>
<saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:artifact</saml1:ConfirmationMethod>
</saml1:SubjectConfirmation>
</saml1:Subject>
<saml1:Attribute AttributeName="samlAuthenticationStatementAuthMethod" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">urn:oasis:names:tc:SAML:1.0:am:password</saml1:AttributeValue>
</saml1:Attribute>
<saml1:Attribute AttributeName="authenticationMethod" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">LdapAuthenticationHandler</saml1:AttributeValue>
</saml1:Attribute>
<saml1:Attribute AttributeName="successfulAuthenticationHandlers" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">LdapAuthenticationHandler</saml1:AttributeValue>
</saml1:Attribute>
</saml1:AttributeStatement>
</saml1:Assertion>
</saml1p:Response>>

What configuration am I missing to return additional attributes now that I have added the SAML dependency? 

Thanks for your consideration,

  Rob Mars.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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/CACjUCoqGMyD_vVaocxvbkes36eLr_3bEfET1u_evNRVZWgp6TA%40mail.gmail.com.

Dmitriy Kopylenko

unread,
Feb 13, 2017, 12:15:53 PM2/13/17
to cas-...@apereo.org

There are 2 pieces to attributes in CAS: 1) resolution, 2) release. First you need to resolve them from the target authentication store (or some other attribute repository), then release them to services.

Cheers,
D.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/etPan.58a1e9c5.4bfcb1cc.e90%40unicon.net.

Dmitriy Kopylenko

unread,
Feb 13, 2017, 12:17:51 PM2/13/17
to cas-...@apereo.org

Rob

unread,
Feb 13, 2017, 1:45:56 PM2/13/17
to cas-...@apereo.org
Hey Dmitriy, 

Thanks for the quick response. Here are my settings for LDAP. I am missing something, I see the attr list var but never see them getting returned. I also attached my log.
##
# LDAP Auth Attributes
#
cas.authn.ldap[0].type=ANONYMOUS
#cas.authn.ldap[0].type=DIRECT
cas.authn.ldap[0].ldapUrl=ldaps://xxx:636
cas.authn.ldap[0].baseDn=xx
cas.authn.ldap[0].userFilter=uid={user}
cas.authn.ldap[0].dnFormat=xxx

cas.authn.ldap[0].principalAttributeId=uid
cas.authn.ldap[0].principalAttributeList=sn,cn:commonName,gn:givenName,xxxPersonUDCID:UDC_IDENTIFIER


##
# LDAP Attributes
#
cas.authn.attributeRepository.ldap.ldapUrl=ldaps://xxx
cas.authn.attributeRepository.ldap.useSsl=true
cas.authn.attributeRepository.ldap.useStartTls=false
cas.authn.attributeRepository.ldap.connectTimeout=5000
cas.authn.attributeRepository.ldap.baseDn=ou=People,o=xxx
cas.authn.attributeRepository.ldap.userFilter=uid={user}
cas.authn.attributeRepository.ldap.subtreeSearch=true
cas.authn.attributeRepository.ldap.bindDn=xxx
cas.authn.attributeRepository.ldap.bindCredential=xxx

##
# Person Directory / Attributes
#
cas.personDirectory.principalAttribute=uid
cas.personDirectory.returnNull=false


This is the log from login page on:




2017-02-13 13:33:06,915 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Bound request context to thread: org.apache.catalina.connector.RequestFacade@11051950>
2017-02-13 13:33:06,915 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <DispatcherServlet with name 'dispatcherServlet' processing POST request for [/cas/login]>
2017-02-13 13:33:06,915 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping@56e0a059] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:06,915 TRACE [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - <No handler mapping found for [/login]>
2017-02-13 13:33:06,915 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.boot.actuate.endpoint.mvc.EndpointHandlerMapping@50dad04a] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:06,918 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping@3c26f017] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:06,918 DEBUG [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] - <Looking up handler method for path /login>
2017-02-13 13:33:06,919 DEBUG [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] - <Did not find handler method for [/login]>
2017-02-13 13:33:06,919 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.web.socket.server.support.WebSocketHandlerMapping@61f41508] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping@565511fd] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - <No handler mapping found for [/login]>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.webflow.mvc.servlet.FlowHandlerMapping@76721043] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:06,920 DEBUG [org.springframework.webflow.mvc.servlet.FlowHandlerMapping] - <Mapping request with URI '/cas/login' to flow with id 'login'>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.pm.config.PasswordManagementConfiguration$1@86f6f5f]>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.pm.config.PasswordManagementConfiguration$1@86f6f5f]>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@1b716faa]>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.config.CasWebflowContextConfiguration$1@75035afd]>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.config.CasWebflowContextConfiguration$1@75035afd]>
2017-02-13 13:33:06,920 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.config.CasWebflowContextConfiguration$3@69470476]>
2017-02-13 13:33:06,920 DEBUG [org.springframework.webflow.executor.FlowExecutorImpl] - <Resuming flow execution with key  xxx
2017-02-13 13:33:06,924 DEBUG [org.apereo.cas.util.EncodingUtils] - <Successfully decoded value. Result in Base64-encoding is xxx>
2017-02-13 13:33:06,931 DEBUG [org.springframework.webflow.definition.registry.FlowDefinitionRegistryImpl] - <Getting FlowDefinition with id 'login'>
2017-02-13 13:33:06,931 DEBUG [org.springframework.webflow.engine.impl.FlowExecutionImpl] - <Resuming in org.springframework.webflow.mvc.servlet.MvcExternalContext@8d73938>
2017-02-13 13:33:06,931 DEBUG [org.springframework.webflow.engine.Flow] - <Restoring [FlowVariable@1065beb9 name = 'credential', valueFactory = [BeanFactoryVariableValueFactory@516854cc type = RememberMeUsernamePasswordCredential]]>
2017-02-13 13:33:06,940 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request does not specify a TARGET or request body is empty>
2017-02-13 13:33:06,940 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4b371b34>
2017-02-13 13:33:06,940 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4b371b34>
2017-02-13 13:33:06,940 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:06,940 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:06,941 DEBUG [org.apereo.cas.services.web.RegisteredServiceThemeBasedViewResolver] - <Attempting to locate views for service [^(https|imaps).*xess.*] with theme [xxx]>
2017-02-13 13:33:06,941 DEBUG [org.apereo.cas.services.web.RegisteredServiceThemeBasedViewResolver] - <Attempting to locate view at classpath:/templates/xxx/casLoginView.html>
2017-02-13 13:33:06,941 DEBUG [org.apereo.cas.services.web.RegisteredServiceThemeBasedViewResolver] - <Found view xxx/casLoginView>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.mvc.view.AbstractMvcView] - <Processing user event 'submit'>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.mvc.view.AbstractMvcView] - <Resolved model null>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.mvc.view.AbstractMvcView] - <Binding to model>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.mvc.view.AbstractMvcView] - <Adding mapping for parameter 'username'>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.mvc.view.AbstractMvcView] - <Adding mapping for parameter 'password'>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.mvc.view.AbstractMvcView] - <Validating model>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.engine.ViewState] - <Event 'submit' returned from view [ServletMvcView@3657f579 view = org.thymeleaf.spring4.view.ThymeleafView@46d1b117]>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@5c7138b1 on = submit, to = realSubmit]>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'viewLoginForm'>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'realSubmit' of flow 'login'>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1190617a expression = authenticationViaFormAction, resultExpression = [null]]>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2017-02-13 13:33:06,942 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.config.CasSupportActionsConfiguration$1@13264eec>
2017-02-13 13:33:06,942 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Located client IP address as 10.48.6.120>
2017-02-13 13:33:06,942 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <User agent Mozilla/5.0 (Windows NT 10.0; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0 is authorized to proceed>
2017-02-13 13:33:06,942 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Adaptive authentication policy has authorized client 10.48.6.120 to proceed.>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Located ticket-granting ticket [null] from the request context>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Located ticket-granting ticket [null] from the request context>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Located service [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check] from the request context>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Located service [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check] from the request context>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Provided value for [renew] request parameter is [null]>
2017-02-13 13:33:06,943 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Provided value for [renew] request parameter is [null]>
2017-02-13 13:33:06,944 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Request is not eligible to be issued service tickets just yet>
2017-02-13 13:33:06,944 DEBUG [org.apereo.cas.web.flow.resolver.impl.ServiceTicketRequestWebflowEventResolver] - <Request is not eligible to be issued service tickets just yet>
2017-02-13 13:33:06,944 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,944 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,945 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@14a71ae1, org.apereo.cas.authentication.LdapAuthenticationHandler@73bd3a0a]>
2017-02-13 13:33:06,945 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Attempting LDAP authentication for jsmith>
2017-02-13 13:33:06,945 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolve user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null]>
2017-02-13 13:33:06,945 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <searching for DN using userFilter>
2017-02-13 13:33:06,945 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2017-02-13 13:33:06,945 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2017-02-13 13:33:06,945 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2017-02-13 13:33:06,945 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@653e7d94>
2017-02-13 13:33:06,945 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2017-02-13 13:33:06,945 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1698537357::config=[org.ldaptive.ConnectionConfig@2121930935::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1072515242::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@2cbd1e99], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1011354801::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@833445435::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@46aed2ee, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b4bf432]>
2017-02-13 13:33:06,954 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2017-02-13 13:33:06,954 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2017-02-13 13:33:06,954 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2017-02-13 13:33:06,954 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@519115725::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2017-02-13 13:33:06,954 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@292946496::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1698537357::config=[org.ldaptive.ConnectionConfig@2121930935::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1072515242::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@2cbd1e99], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1011354801::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@833445435::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@46aed2ee, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b4bf432]>
2017-02-13 13:33:06,954 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@1698537357::config=[org.ldaptive.ConnectionConfig@2121930935::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1072515242::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@2cbd1e99], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1011354801::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@833445435::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@46aed2ee, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b4bf432] = true>
2017-02-13 13:33:06,954 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-1719668278::baseDn=ou=People,o=xxx, searchFilter=[org.ldaptive.SearchFilter@-1111612539::filter=uid={user}, parameters={context=null, user=jsmith}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1698537357::config=[org.ldaptive.ConnectionConfig@2121930935::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1072515242::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@2cbd1e99], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1011354801::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@833445435::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@46aed2ee, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b4bf432]>
2017-02-13 13:33:06,969 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: uid=jsmith,ou=People,o=xxx: null:null:No attributes>
2017-02-13 13:33:06,969 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn 'uid=jsmith,ou=People,o=xxx'>
2017-02-13 13:33:06,969 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn 'uid=jsmith,ou=People,o=xxx'>
2017-02-13 13:33:06,969 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@225557376::searchEntry=[dn=uid=jsmith,ou=People,o=xxx[], responseControls=null, messageId=-1]]>
2017-02-13 13:33:06,970 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1709003814::result=[org.ldaptive.SearchResult@-1656788882::entries=[[dn=uid=jsmith,ou=People,o=xxx[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1719668278::baseDn=ou=People,o=xxx, searchFilter=[org.ldaptive.SearchFilter@-1111612539::filter=uid={user}, parameters={context=null, user=jsmith}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1698537357::config=[org.ldaptive.ConnectionConfig@2121930935::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1072515242::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@2cbd1e99], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1011354801::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@833445435::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@46aed2ee, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b4bf432]>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@653e7d94>
2017-02-13 13:33:06,970 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolved dn=uid=jsmith,ou=People,o=xxx for user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null]>
2017-02-13 13:33:06,970 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate dn=uid=jsmith,ou=People,o=xxx with request=[org.ldaptive.auth.AuthenticationRequest@1931762731::user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID]]>
2017-02-13 13:33:06,970 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@1390490637::dn=uid=jsmith,ou=People,o=xxx, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1389115498::user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID]]]>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@15651510>
2017-02-13 13:33:06,970 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2017-02-13 13:33:06,970 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96]>
2017-02-13 13:33:06,976 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2017-02-13 13:33:06,976 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2017-02-13 13:33:06,976 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2017-02-13 13:33:06,976 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@1572809329::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2017-02-13 13:33:06,977 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@204202217::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96]>
2017-02-13 13:33:06,977 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96] = true>
2017-02-13 13:33:06,977 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1471282237::bindDn=uid=jsmith,ou=People,o=xxx, saslConfig=null, controls=[[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]], referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96]>
2017-02-13 13:33:06,977 TRACE [org.ldaptive.provider.ControlProcessor] - <processing request controls: [[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]>
2017-02-13 13:33:06,977 TRACE [org.ldaptive.provider.ControlProcessor] - <produced provider request controls: [javax.naming.ldap.BasicControl@40c5d38b]>
2017-02-13 13:33:06,981 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@330981330::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@1471282237::bindDn=uid=jsmith,ou=People,o=xxx, saslConfig=null, controls=[[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]], referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96]>
2017-02-13 13:33:06,981 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1269963148::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96], result=true, resultCode=SUCCESS, message=null, controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@1390490637::dn=uid=jsmith,ou=People,o=xxx, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1389115498::user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID]]]>
2017-02-13 13:33:06,981 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <resolve criteria=[org.ldaptive.auth.AuthenticationCriteria@1390490637::dn=uid=jsmith,ou=People,o=xxx, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1389115498::user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID]]]>
2017-02-13 13:33:06,981 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2017-02-13 13:33:06,981 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2017-02-13 13:33:06,981 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2017-02-13 13:33:06,981 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@1c775a6d>
2017-02-13 13:33:06,981 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2017-02-13 13:33:06,981 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@477527142::config=[org.ldaptive.ConnectionConfig@129741316::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@935492740::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@32ca8005], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@177571235::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1836903123::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@218c5b5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@f265ec]>
2017-02-13 13:33:06,985 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2017-02-13 13:33:06,985 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2017-02-13 13:33:06,985 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2017-02-13 13:33:06,985 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@1136220922::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2017-02-13 13:33:06,986 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@764317837::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@477527142::config=[org.ldaptive.ConnectionConfig@129741316::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@935492740::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@32ca8005], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@177571235::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1836903123::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@218c5b5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@f265ec]>
2017-02-13 13:33:06,986 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@477527142::config=[org.ldaptive.ConnectionConfig@129741316::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@935492740::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@32ca8005], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@177571235::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1836903123::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@218c5b5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@f265ec] = true>
2017-02-13 13:33:06,986 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <searching for entry using userFilter>
2017-02-13 13:33:06,986 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@368853771::baseDn=ou=People,o=xxx, searchFilter=[org.ldaptive.SearchFilter@1819814558::filter=uid={user}, parameters={context=null, dn=uid=jsmith,ou=People,o=xxx, user=jsmith}], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@477527142::config=[org.ldaptive.ConnectionConfig@129741316::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@935492740::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@32ca8005], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@177571235::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1836903123::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@218c5b5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@f265ec]>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: uid=jsmith,ou=People,o=xxx: null:null:{uid=uid: jsmith, sn=sn: Smith}>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn 'uid=jsmith,ou=People,o=xxx'>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn 'uid=jsmith,ou=People,o=xxx'>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@1812663841::searchEntry=[dn=uid=jsmith,ou=People,o=xxx[[uid[jsmith]], [sn[Smith]]], responseControls=null, messageId=-1]]>
2017-02-13 13:33:06,994 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@934151253::result=[org.ldaptive.SearchResult@-1477635031::entries=[[dn=uid=jsmith,ou=People,o=xxx[[uid[jsmith]], [sn[Smith]]], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@368853771::baseDn=ou=People,o=xxx, searchFilter=[org.ldaptive.SearchFilter@1819814558::filter=uid={user}, parameters={context=null, dn=uid=jsmith,ou=People,o=xxx, user=jsmith}], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@477527142::config=[org.ldaptive.ConnectionConfig@129741316::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@935492740::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@32ca8005], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@177571235::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1836903123::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@218c5b5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@f265ec]>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@1c775a6d>
2017-02-13 13:33:06,994 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <resolved result=[org.ldaptive.SearchResult@-1477635031::entries=[[dn=uid=jsmith,ou=People,o=xxx[[uid[jsmith]], [sn[Smith]]], responseControls=null, messageId=-1]], references=[]] for criteria=[org.ldaptive.auth.AuthenticationCriteria@1390490637::dn=uid=jsmith,ou=People,o=xxx, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1389115498::user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID]]]>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.auth.Authenticator] - <resolved entry=[dn=uid=jsmith,ou=People,o=xxx[[uid[jsmith]], [sn[Smith]]], responseControls=null, messageId=-1] with resolver=[org.ldaptive.auth.PooledSearchEntryResolver@1151271440::factory=[org.ldaptive.pool.PooledConnectionFactory@1511862682::pool=[org.ldaptive.pool.BlockingConnectionPool@1606414348::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@921728640::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@89016627::searchRequest=[org.ldaptive.SearchRequest@-430236897::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@293953132::prunePeriod=PT1H23M20S, idleTime=PT1H23M20S], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1741198468::provider=org.ldaptive.provider.jndi.JndiProvider@43cae2a5, config=[org.ldaptive.ConnectionConfig@129741316::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@935492740::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@32ca8005]], initialized=true, availableCount=3, activeCount=0]], baseDn=ou=People,o=xxx, userFilter=uid={user}, userFilterParameters=null, allowMultipleEntries=false, subtreeSearch=true, derefAliases=null, referralHandler=null, searchEntryHandlers=null]>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2017-02-13 13:33:06,994 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@15651510>
2017-02-13 13:33:06,994 INFO [org.ldaptive.auth.Authenticator] - <Authentication succeeded for dn: uid=jsmith,ou=People,o=xxx>
2017-02-13 13:33:06,994 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1269963148::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@358889225::config=[org.ldaptive.ConnectionConfig@722639167::ldapUrl=ldaps://testedir.xxx.edu:636, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@279232568::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@55bce52], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@802075832::metadata=[ldapUrl=ldaps://testedir.xxx.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@703499337::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@74825d50, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@7af7cc96], result=true, resultCode=SUCCESS, message=null, controls=null] for dn=uid=jsmith,ou=People,o=xxx with request=[org.ldaptive.auth.AuthenticationRequest@1389115498::user=[org.ldaptive.auth.User@1704049314::identifier=jsmith, context=null], returnAttributes=[uid, gn, sn, cn, xxxPersonUDCID, gn, sn, cn, xxxPersonUDCID]]>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response: [org.ldaptive.auth.AuthenticationResponse@1053423312::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=uid=jsmith,ou=People,o=xxx, ldapEntry=[dn=uid=jsmith,ou=People,o=xxx[[uid[jsmith]], [sn[Smith]]], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Applying password policy to [org.ldaptive.auth.AuthenticationResponse@1053423312::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=uid=jsmith,ou=People,o=xxx, ldapEntry=[dn=uid=jsmith,ou=People,o=xxx[[uid[jsmith]], [sn[Smith]]], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.support.DefaultAccountStateHandler] - <Account state not defined. Returning empty list of messages.>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response returned as result. Creating the final LDAP principal>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Creating LDAP principal for jsmith based on uid=jsmith,ou=People,o=xxx>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Retrieved principal id attribute jsmith>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [sn[Smith]]>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Created LDAP principal for id jsmith and 2 attributes>
2017-02-13 13:33:06,994 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated jsmith>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <No resolver configured for LdapAuthenticationHandler. Falling back to handler principal jsmith>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is jsmith>
2017-02-13 13:33:06,994 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2017-02-13 13:33:06,994 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated principal [jsmith] and attributes {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith} with credentials [jsmith].>
2017-02-13 13:33:06,995 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Authentication org.apereo.cas.authentication.AbstractAuthenticationManager.authenticate(AuthenticationTransaction))]>
2017-02-13 13:33:07,012 Log4j2-AsyncLoggerConfig-10 ERROR An exception occurred processing Appender casAudit java.lang.IllegalArgumentException: No log appender could be found for auditlogfile
        at org.apereo.cas.logging.CasAppender.append(CasAppender.java:77)
        at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:155)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:128)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:119)
        at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
        at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
        at org.apache.logging.log4j.core.async.AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:113)
        at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:111)
        at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:97)
        at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

2017-02-13 13:33:06,995 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: jsmith
WHAT: Supplied credentials: [jsmith]
ACTION: AUTHENTICATION_SUCCESS
APPLICATION: CAS
WHEN: Mon Feb 13 13:33:06 EST 2017
CLIENT IP ADDRESS: 10.48.6.120
SERVER IP ADDRESS: 10.13.10.67
=============================================================

>
2017-02-13 13:33:06,996 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@4b03c956]>
2017-02-13 13:33:06,996 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Locating service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check in service registry to determine authentication policy>
2017-02-13 13:33:06,996 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Locating service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check in service registry to determine authentication policy>
2017-02-13 13:33:06,997 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via AdaptiveMultifactorAuthenticationWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:06,997 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via AdaptiveMultifactorAuthenticationWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:06,997 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,997 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,998 DEBUG [org.apereo.cas.web.flow.resolver.impl.AdaptiveMultifactorAuthenticationWebflowEventResolver] - <Adaptive authentication is not configured to require multifactor authentication>
2017-02-13 13:33:06,998 DEBUG [org.apereo.cas.web.flow.resolver.impl.AdaptiveMultifactorAuthenticationWebflowEventResolver] - <Adaptive authentication is not configured to require multifactor authentication>
2017-02-13 13:33:06,998 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for AdaptiveMultifactorAuthenticationWebflowEventResolver is blank/ignored>
2017-02-13 13:33:06,998 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for AdaptiveMultifactorAuthenticationWebflowEventResolver is blank/ignored>
2017-02-13 13:33:06,999 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via GlobalAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:06,999 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via GlobalAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:06,999 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,999 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:06,999 DEBUG [org.apereo.cas.web.flow.resolver.impl.GlobalAuthenticationPolicyWebflowEventResolver] - <No value could be found for request parameter null>
2017-02-13 13:33:06,999 DEBUG [org.apereo.cas.web.flow.resolver.impl.GlobalAuthenticationPolicyWebflowEventResolver] - <No value could be found for request parameter null>
2017-02-13 13:33:07,000 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for GlobalAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,000 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for GlobalAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,000 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RequestParameterAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,000 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RequestParameterAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,001 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,001 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,001 DEBUG [org.apereo.cas.web.flow.resolver.impl.RequestParameterAuthenticationPolicyWebflowEventResolver] - <No value could be found for request parameter authn_method>
2017-02-13 13:33:07,001 DEBUG [org.apereo.cas.web.flow.resolver.impl.RequestParameterAuthenticationPolicyWebflowEventResolver] - <No value could be found for request parameter authn_method>
2017-02-13 13:33:07,001 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RequestParameterAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,001 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RequestParameterAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,002 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RestEndpointAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,002 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RestEndpointAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,002 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,002 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,002 DEBUG [org.apereo.cas.web.flow.resolver.impl.RestEndpointAuthenticationPolicyWebflowEventResolver] - <Rest endpoint to determine event is not configured for jsmith>
2017-02-13 13:33:07,002 DEBUG [org.apereo.cas.web.flow.resolver.impl.RestEndpointAuthenticationPolicyWebflowEventResolver] - <Rest endpoint to determine event is not configured for jsmith>
2017-02-13 13:33:07,003 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RestEndpointAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,003 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RestEndpointAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,003 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,003 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,003 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,003 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,004 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Authentication policy is absent or does not contain any multifactor authentication providers>
2017-02-13 13:33:07,004 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Authentication policy is absent or does not contain any multifactor authentication providers>
2017-02-13 13:33:07,004 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,004 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,005 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via PrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,005 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via PrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,005 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,005 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,005 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Attribute name to determine event is not configured for jsmith>
2017-02-13 13:33:07,005 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Attribute name to determine event is not configured for jsmith>
2017-02-13 13:33:07,006 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for PrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,006 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for PrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,006 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServiceAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,006 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServiceAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps).*xess.* and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,006 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,006 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2017-02-13 13:33:07,007 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Authentication policy does not contain any multifactor authentication providers>
2017-02-13 13:33:07,007 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Authentication policy does not contain any multifactor authentication providers>
2017-02-13 13:33:07,007 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServiceAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,007 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServiceAuthenticationPolicyWebflowEventResolver is blank/ignored>
2017-02-13 13:33:07,008 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Finalizing authentication transactions and issuing ticket-granting ticket>
2017-02-13 13:33:07,008 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Finalizing authentication transactions and issuing ticket-granting ticket>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [jsmith] for inclusion in result>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}] for inclusion in this result for principal [jsmith]>
2017-02-13 13:33:07,009 WARN [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication attribute [samlAuthenticationStatementAuthMethod] has no value and is not collected>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [jsmith] as the primary principal>
2017-02-13 13:33:07,009 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [jsmith]>
2017-02-13 13:33:07,017 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2017-02-13 13:33:07,017 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2017-02-13T13:33:07.017-05:00[America/New_York]]>
2017-02-13 13:33:07,017 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@a5921729 and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,018 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jsmith>
2017-02-13 13:33:07,018 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}]>
2017-02-13 13:33:07,018 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [2] cached attributes for principal [jsmith] that are {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}>
2017-02-13 13:33:07,018 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith} for jsmith>
2017-02-13 13:33:07,018 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnMappedAttributeReleasePolicy to process attributes for jsmith>
2017-02-13 13:33:07,022 DEBUG [org.apereo.cas.services.ReturnMappedAttributeReleasePolicy] - <Found attribute [sn] in the list of allowed attributes, mapped to the name [sn]>
2017-02-13 13:33:07,023 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnMappedAttributeReleasePolicy allows release of {sn=Smith} for jsmith>
2017-02-13 13:33:07,023 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2017-02-13 13:33:07,023 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2017-02-13 13:33:07,024 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2017-02-13 13:33:07,024 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2017-02-13 13:33:07,024 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2017-02-13 13:33:07,025 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2017-02-13 13:33:07,025 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2017-02-13 13:33:07,026 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {sn=Smith}>
2017-02-13 13:33:07,026 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2017-02-13 13:33:07,026 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-**********************************************GAqIwdZ7ns-vml01006] to registry.>
2017-02-13 13:33:07,027 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasTicketGrantingTicketCreatedEvent@2e9c5d9[ticketGrantingTicket=TGT-**********************************************GAqIwdZ7ns-vml01006]>
2017-02-13 13:33:07,027 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(TicketGrantingTicket org.apereo.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket(AuthenticationResult))]>
2017-02-13 13:33:07,028 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: jsmith
WHAT: TGT-**********************************************GAqIwdZ7ns-vml01006
ACTION: TICKET_GRANTING_TICKET_CREATED
APPLICATION: CAS
WHEN: Mon Feb 13 13:33:07 EST 2017
CLIENT IP ADDRESS: 10.48.6.120
SERVER IP ADDRESS: 10.13.10.67
=============================================================

>
2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resolved single event [success] via [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] for this context>
2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resolved single event [success] via [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] for this context>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.config.CasSupportActionsConfiguration$1@13264eec; result = success>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1190617a expression = authenticationViaFormAction, resultExpression = [null]]; result = success>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@6cda133 on = success, to = sendTicketGrantingTicket]>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'realSubmit'>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'sendTicketGrantingTicket' of flow 'login'>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@1d2a481b expression = sendTicketGrantingTicketAction, resultExpression = [null]]>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2017-02-13 13:33:07,029 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.SendTicketGrantingTicketAction@14e910f6>
2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.flow.SendTicketGrantingTicketAction] - <Setting TGC for current session.>
2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.flow.SendTicketGrantingTicketAction] - <Setting TGC for current session.>
2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-2-FIbDHyBrdFS0kM03oa7HKSEEud...@10.48.6.120@Mozilla/5.0 (Windows NT 10.0; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0]>
2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-**********************************************GAqIwdZ7n...@10.48.6.120@Mozilla/5.0 (Windows NT 10.0; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0]>
2017-02-13 13:33:07,030 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Encrypting via [A128CBC-HS256]>
2017-02-13 13:33:07,031 DEBUG [org.apereo.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Added cookie with name [TGC] and value [eyJhbGciOiJIUzUxMiJ9.WlhsS2FHSkhZMmxQYVVwcllWaEphVXhEU214aWJVMXBUMmxLUWsxVVNUUlJNRXBFVEZWb1ZFMXFWVEpKYmpBdUxtVmlWSFJ0TUVORFRucFZTRWRSZDJOTFFuQkVhbWN1UldNMFlpMU5WRk5sWDJOcFgwZzVWM2xsWW10SVJrdHZXbTFNYkZObFJ6WjNhSFZDV0hSa1Z6TllYM1oxUW5WUlVUbFZWRE5uTmpoUmNESnFNa2xHUVZJMmRETTRWalJEWVMxTFlVbE1kWHBzUld0cFlsOTRTbXR1TXpSNllVeGFPRU41YW1ka2JGWnpaRGR6Ylc0MFdreGpNMDVCZUU0MFZFUkpla2wxTVZvdGJDMXVWWFZDWW5SdVpuZDZUVVJDU0doSFgyZFlWVU5mVEVablNuTnZWRkZaVG10emFVMUZWeTE1ZW5keVdHZDBXbWRLYjFkb1NIYzFabGxzWlV0Wk1VSnVRMmg0VjNGQ2FtSmpVSEJhUTFaMmEyVTVVUzVFZVhwZmJtZHdWR3BEZDFSdVNqZG9Sa3BYYkRKMw.Wvo8e-2Y4ns2a2xVmUCbFIoqV_iBoKa1N0lHxMjCzw4yO0C-dxaiXduzse0csr_4-R-W8oGg1dnV9ZEKjudtIA]>
2017-02-13 13:33:07,031 DEBUG [org.apereo.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Added cookie with name [TGC] and value [eyJhbGciOiJIUzUxMiJ9.WlhsS2FHSkhZMmxQYVVwcllWaEphVXhEU214aWJVMXBUMmxLUWsxVVNUUlJNRXBFVEZWb1ZFMXFWVEpKYmpBdUxtVmlWSFJ0TUVORFRucFZTRWRSZDJOTFFuQkVhbWN1UldNMFlpMU5WRk5sWDJOcFgwZzVWM2xsWW10SVJrdHZXbTFNYkZObFJ6WjNhSFZDV0hSa1Z6TllYM1oxUW5WUlVUbFZWRE5uTmpoUmNESnFNa2xHUVZJMmRETTRWalJEWVMxTFlVbE1kWHBzUld0cFlsOTRTbXR1TXpSNllVeGFPRU41YW1ka2JGWnpaRGR6Ylc0MFdreGpNMDVCZUU0MFZFUkpla2wxTVZvdGJDMXVWWFZDWW5SdVpuZDZUVVJDU0doSFgyZFlWVU5mVEVablNuTnZWRkZaVG10emFVMUZWeTE1ZW5keVdHZDBXbWRLYjFkb1NIYzFabGxzWlV0Wk1VSnVRMmg0VjNGQ2FtSmpVSEJhUTFaMmEyVTVVUzVFZVhwZmJtZHdWR3BEZDFSdVNqZG9Sa3BYYkRKMw.Wvo8e-2Y4ns2a2xVmUCbFIoqV_iBoKa1N0lHxMjCzw4yO0C-dxaiXduzse0csr_4-R-W8oGg1dnV9ZEKjudtIA]>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.SendTicketGrantingTicketAction@14e910f6; result = success>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@1d2a481b expression = sendTicketGrantingTicketAction, resultExpression = [null]]; result = success>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@35352386 on = *, to = serviceCheck]>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'sendTicketGrantingTicket'>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'serviceCheck' of flow 'login'>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@6125ce8c on = flowScope.service != null, to = generateServiceTicket]>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'serviceCheck'>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'generateServiceTicket' of flow 'login'>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@729a4de9 expression = generateServiceTicketAction, resultExpression = [null]]>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2017-02-13 13:33:07,032 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.apereo.cas.web.flow.GenerateServiceTicketAction@68645262>
2017-02-13 13:33:07,032 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,032 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,033 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2017-02-13 13:33:07,033 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [jsmith] for inclusion in result>
2017-02-13 13:33:07,033 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}] for inclusion in this result for principal [jsmith]>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [jsmith] as the primary principal>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [jsmith]>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2017-02-13T13:33:07.036-05:00[America/New_York]]>
2017-02-13 13:33:07,036 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@a5f78be9 and service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,036 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,037 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,037 DEBUG [org.apereo.cas.ticket.support.RememberMeDelegatingExpirationPolicy] - <Ticket is not associated with a remember-me authentication. Invoking org.apereo.cas.ticket.support.TicketGrantingTicketExpirationPolicy@2274bdf3>
2017-02-13 13:33:07,038 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jsmith>
2017-02-13 13:33:07,038 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}]>
2017-02-13 13:33:07,038 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [2] cached attributes for principal [jsmith] that are {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}>
2017-02-13 13:33:07,038 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith} for jsmith>
2017-02-13 13:33:07,039 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnMappedAttributeReleasePolicy to process attributes for jsmith>
2017-02-13 13:33:07,039 DEBUG [org.apereo.cas.services.ReturnMappedAttributeReleasePolicy] - <Found attribute [sn] in the list of allowed attributes, mapped to the name [sn]>
2017-02-13 13:33:07,039 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnMappedAttributeReleasePolicy allows release of {sn=Smith} for jsmith>
2017-02-13 13:33:07,040 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2017-02-13 13:33:07,040 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2017-02-13 13:33:07,040 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2017-02-13 13:33:07,041 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2017-02-13 13:33:07,041 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2017-02-13 13:33:07,041 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2017-02-13 13:33:07,042 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2017-02-13 13:33:07,042 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {sn=Smith}>
2017-02-13 13:33:07,042 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2017-02-13 13:33:07,043 DEBUG [org.apereo.cas.services.RegisteredServiceAccessStrategyUtils] - <Current authentication via ticket TGT-**********************************************GAqIwdZ7ns-vml01006 allows service https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check to participate in the existing SSO session>
2017-02-13 13:33:07,043 TRACE [org.apereo.cas.CentralAuthenticationServiceImpl] - <TGT-TGT is not proxied by another service>
2017-02-13 13:33:07,043 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Looking up service ticket id generator for [org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2017-02-13 13:33:07,044 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Attempting to encode service ticket ST-2-pK0KpdwRPPMwLvdEBOee-vml01006>
2017-02-13 13:33:07,044 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Encoded service ticket id ST-2-pK0KpdwRPPMwLvdEBOee-vml01006>
2017-02-13 13:33:07,045 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-**********************************************GAqIwdZ7ns-vml01006] to registry.>
2017-02-13 13:33:07,045 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [ST-2-pK0KpdwRPPMwLvdEBOee-vml01006] to registry.>
2017-02-13 13:33:07,046 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-2-pK0KpdwRPPMwLvdEBOee-vml01006] for service [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check] and principal [jsmith]>
2017-02-13 13:33:07,046 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketGrantedEvent@4e2fe88e[ticketGrantingTicket=TGT-**********************************************GAqIwdZ7ns-vml01006,serviceTicket=ST-2-pK0KpdwRPPMwLvdEBOee-vml01006]>
2017-02-13 13:33:07,046 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(ServiceTicket org.apereo.cas.CentralAuthenticationServiceImpl.grantServiceTicket(String,Service,AuthenticationResult))]>
2017-02-13 13:33:07,047 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: jsmith
ACTION: SERVICE_TICKET_CREATED
APPLICATION: CAS
WHEN: Mon Feb 13 13:33:07 EST 2017
CLIENT IP ADDRESS: 10.48.6.120
SERVER IP ADDRESS: 10.13.10.67
=============================================================

>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.apereo.cas.web.flow.GenerateServiceTicketAction@68645262; result = success>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@729a4de9 expression = generateServiceTicketAction, resultExpression = [null]]; result = success>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@6e14bc7f on = success, to = redirect]>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'generateServiceTicket'>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.engine.ActionState] - <Entering state 'redirect' of flow 'login'>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing [EvaluateAction@51aebc60 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]>
2017-02-13 13:33:07,047 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Putting action execution attributes map[[empty]]>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.execution.AnnotatedAction] - <Clearing action execution attributes map[[empty]]>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing [EvaluateAction@51aebc60 expression = flowScope.service.getResponse(requestScope.serviceTicketId), resultExpression = requestScope.response]; result = success>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@3bce2e9f on = *, to = postRedirectDecision]>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'redirect'>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.DecisionState] - <Entering state 'postRedirectDecision' of flow 'login'>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Executing [Transition@2ff31fdc on = *, to = redirectView]>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Exiting state 'postRedirectDecision'>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.EndState] - <Entering state 'redirectView' of flow 'login'>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ViewFactoryActionAdapter@6991f05c>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Executing org.springframework.webflow.action.ExternalRedirectAction@272323b8>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ExternalRedirectAction@272323b8; result = success>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.execution.ActionExecutor] - <Finished executing org.springframework.webflow.action.ViewFactoryActionAdapter@6991f05c; result = success>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.engine.Transition] - <Completed transition execution.  As a result, the flow execution has ended>
2017-02-13 13:33:07,048 DEBUG [org.springframework.webflow.mvc.servlet.FlowHandlerAdapter] - <Sending external redirect to 'https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check?ticket=ST-2-pK0KpdwRPPMwLvdEBOee-vml01006'>
2017-02-13 13:33:07,048 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling>
2017-02-13 13:33:07,048 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Cleared thread-bound request context: org.apache.catalina.connector.RequestFacade@11051950>
2017-02-13 13:33:07,048 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Successfully completed request>
2017-02-13 13:33:07,092 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Bound request context to thread: org.apache.catalina.connector.RequestFacade@11051950>
2017-02-13 13:33:07,092 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <DispatcherServlet with name 'dispatcherServlet' processing POST request for [/cas/samlValidate]>
2017-02-13 13:33:07,092 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping@56e0a059] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:07,092 TRACE [org.springframework.web.servlet.handler.SimpleUrlHandlerMapping] - <No handler mapping found for [/samlValidate]>
2017-02-13 13:33:07,092 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.boot.actuate.endpoint.mvc.EndpointHandlerMapping@50dad04a] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:07,094 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler map [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping@3c26f017] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:07,094 DEBUG [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] - <Looking up handler method for path /samlValidate>
2017-02-13 13:33:07,094 TRACE [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] - <Found 1 matching mapping(s) for [/samlValidate] : [{[/samlValidate],methods=[POST]}]>
2017-02-13 13:33:07,094 DEBUG [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] - <Returning handler method [protected org.springframework.web.servlet.ModelAndView org.apereo.cas.support.saml.web.SamlValidateController.handleRequestInternal(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse) throws java.lang.Exception]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.pm.config.PasswordManagementConfiguration$1@86f6f5f]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.pm.config.PasswordManagementConfiguration$1@86f6f5f]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter@1b716faa]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.config.CasWebflowContextConfiguration$1@75035afd]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.config.CasWebflowContextConfiguration$1@75035afd]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.apereo.cas.config.CasWebflowContextConfiguration$3@69470476]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Testing handler adapter [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter@229e79c8]>
2017-02-13 13:33:07,095 DEBUG [org.springframework.web.servlet.mvc.WebContentInterceptor] - <Looking up cache seconds for [/samlValidate]>
2017-02-13 13:33:07,095 DEBUG [org.springframework.web.servlet.mvc.WebContentInterceptor] - <Applying default cache seconds to [/samlValidate]>
2017-02-13 13:33:07,095 TRACE [org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod] - <Invoking 'org.apereo.cas.support.saml.web.SamlValidateController.handleRequestInternal' with arguments [org.apache.catalina.connector.RequestFacade@11051950, org.springframework.boot.web.support.ErrorPageFilter$ErrorWrapperResponse@50d2569]>
2017-02-13 13:33:07,096 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request Body: <SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/"><SOAP-ENV:Header/><SOAP-ENV:Body><samlp:Request xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol"  MajorVersion="1" MinorVersion="1" RequestID="13368bfa-2a09-4c2e-89d0-31c6a66309a7" IssueInstant="2017-02-13T13:33:07Z"><samlp:AssertionArtifact>ST-2-pK0KpdwRPPMwLvdEBOee-vml01006</samlp:AssertionArtifact></samlp:Request></SOAP-ENV:Body></SOAP-ENV:Envelope>>
2017-02-13 13:33:07,096 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Extracted ArtifactId: ST-2-pK0KpdwRPPMwLvdEBOee-vml01006. extracted Request Id: 13368bfa-2a09-4c2e-89d0-31c6a66309a7>
2017-02-13 13:33:07,097 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check based on org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory@3f3ef70f>
2017-02-13 13:33:07,097 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check based on org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory@3f3ef70f>
2017-02-13 13:33:07,097 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.support.saml.authentication.principal.SamlService for: https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,097 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.support.saml.authentication.principal.SamlService for: https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,097 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Attempting to decode service ticket ST-2-pK0KpdwRPPMwLvdEBOee-vml01006 to verify authenticity>
2017-02-13 13:33:07,098 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,098 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,099 DEBUG [org.apereo.cas.ticket.support.RememberMeDelegatingExpirationPolicy] - <Ticket is not associated with a remember-me authentication. Invoking org.apereo.cas.ticket.support.TicketGrantingTicketExpirationPolicy@2274bdf3>
2017-02-13 13:33:07,099 DEBUG [org.apereo.cas.ticket.support.RememberMeDelegatingExpirationPolicy] - <Ticket is not associated with a remember-me authentication. Invoking org.apereo.cas.ticket.support.TicketGrantingTicketExpirationPolicy@2274bdf3>
2017-02-13 13:33:07,100 TRACE [org.apereo.cas.support.saml.authentication.principal.SamlService] - <Decoded urls and comparing [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check] with [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check]>
2017-02-13 13:33:07,100 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Located registered service definition id=10000005,name=xess,description=XE Apps,serviceId=^(https|imaps).*xess.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=xxx,evaluationOrder=1,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnMappedAttributeReleasePolicy@559de1b8[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@1dd7717f[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes={eduPersonAffiliation=eduPersonAffiliation, eduPersonPrincipalName=eduPersonPrincipalName, employeeID=employeeID, xxxPersonIdmRoles=xxxPersonIdmRoles, xxxPersonUDCID=UDC_IDENTIFIER, givenName=givenName, mail=mail, sn=sn, uid=uid}],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@1ac3fc72[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RegexMatchingRegisteredServiceProxyPolicy@3e5f1e80[^https?://.*],logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@7c9812c9[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> from https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check to handle validation request>
2017-02-13 13:33:07,100 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Attribute policy [org.apereo.cas.services.ReturnMappedAttributeReleasePolicy@559de1b8[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@1dd7717f[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes={eduPersonAffiliation=eduPersonAffiliation, eduPersonPrincipalName=eduPersonPrincipalName, employeeID=employeeID, xxxPersonIdmRoles=xxxPersonIdmRoles, xxxPersonUDCID=UDC_IDENTIFIER, givenName=givenName, mail=mail, sn=sn, uid=uid}]] is associated with service [id=10000005,name=xess,description=XE Apps,serviceId=^(https|imaps).*xess.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=xxx,evaluationOrder=1,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnMappedAttributeReleasePolicy@559de1b8[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@1dd7717f[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes={eduPersonAffiliation=eduPersonAffiliation, eduPersonPrincipalName=eduPersonPrincipalName, employeeID=employeeID, xxxPersonIdmRoles=xxxPersonIdmRoles, xxxPersonUDCID=UDC_IDENTIFIER, givenName=givenName, mail=mail, sn=sn, uid=uid}],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@1ac3fc72[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RegexMatchingRegisteredServiceProxyPolicy@3e5f1e80[^https?://.*],logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@7c9812c9[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null>]>
2017-02-13 13:33:07,101 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jsmith>
2017-02-13 13:33:07,103 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}]>
2017-02-13 13:33:07,103 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [2] cached attributes for principal [jsmith] that are {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith}>
2017-02-13 13:33:07,103 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {LdapAuthenticationHandler.dn=uid=jsmith,ou=People,o=xxx, sn=Smith} for jsmith>
2017-02-13 13:33:07,103 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnMappedAttributeReleasePolicy to process attributes for jsmith>
2017-02-13 13:33:07,104 DEBUG [org.apereo.cas.services.ReturnMappedAttributeReleasePolicy] - <Found attribute [sn] in the list of allowed attributes, mapped to the name [sn]>
2017-02-13 13:33:07,104 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnMappedAttributeReleasePolicy allows release of {sn=Smith} for jsmith>
2017-02-13 13:33:07,104 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2017-02-13 13:33:07,105 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2017-02-13 13:33:07,105 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2017-02-13 13:33:07,105 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2017-02-13 13:33:07,106 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2017-02-13 13:33:07,106 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2017-02-13 13:33:07,106 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2017-02-13 13:33:07,107 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {sn=Smith}>
2017-02-13 13:33:07,107 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider] - <Returning the default principal id [jsmith] for username.>
2017-02-13 13:33:07,108 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketValidatedEvent@4609dcbd[assertion=org.apereo.cas.authentication.DefaultAuthentication@a5921729:https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check,serviceTicket=ST-2-pK0KpdwRPPMwLvdEBOee-vml01006]>
2017-02-13 13:33:07,108 DEBUG [org.apereo.cas.ticket.support.MultiTimeUseOrTimeoutExpirationPolicy] - <Ticket usage count 1 is greater than or equal to 1>
2017-02-13 13:33:07,108 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,109 TRACE [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Ticket encryption is not enabled. Falling back to default behavior>
2017-02-13 13:33:07,111 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket [ST-2-pK0KpdwRPPMwLvdEBOee-vml01006] from the registry.>
2017-02-13 13:33:07,111 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Assertion org.apereo.cas.CentralAuthenticationServiceImpl.validateServiceTicket(String,Service))]>
2017-02-13 13:33:07,112 INFO [org.apereo.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
=============================================================
WHO: jsmith
WHAT: ST-2-pK0KpdwRPPMwLvdEBOee-vml01006
ACTION: SERVICE_TICKET_VALIDATED
APPLICATION: CAS
WHEN: Mon Feb 13 13:33:07 EST 2017
CLIENT IP ADDRESS: 10.13.9.12
SERVER IP ADDRESS: 10.13.10.67
=============================================================

>
2017-02-13 13:33:07,113 DEBUG [org.apereo.cas.validation.Cas20WithoutProxyingValidationSpecification] - <Number of chained authentications in the assertion 1>
2017-02-13 13:33:07,113 DEBUG [org.apereo.cas.support.saml.web.SamlValidateController] - <Locating the primary authentication associated with this service request https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,113 DEBUG [org.apereo.cas.support.saml.web.SamlValidateController] - <No particular authentication context is required for this request>
2017-02-13 13:33:07,114 DEBUG [org.apereo.cas.support.saml.web.SamlValidateController] - <No service credentials specified, and/or the proxy handler [org.apereo.cas.ticket.proxy.support.Cas20ProxyHandler@74a45c6b] cannot handle credentials>
2017-02-13 13:33:07,114 DEBUG [org.apereo.cas.support.saml.web.SamlValidateController] - <Successfully validated service ticket ST-2-pK0KpdwRPPMwLvdEBOee-vml01006 for service [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check]>
2017-02-13 13:33:07,114 TRACE [org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod] - <Method [org.apereo.cas.support.saml.web.SamlValidateController.handleRequestInternal] returned [ModelAndView: materialized View is [org.apereo.cas.support.saml.web.view.Saml10SuccessResponseView: name 'scopedTarget.casSamlServiceSuccessView']; model is {assertion=org.apereo.cas.authentication.DefaultAuthentication@a5921729:https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check, service=https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check, pgtIou=null}]>
2017-02-13 13:33:07,115 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Rendering view [org.apereo.cas.support.saml.web.view.Saml10SuccessResponseView: name 'scopedTarget.casSamlServiceSuccessView'] in DispatcherServlet with name 'dispatcherServlet'>
2017-02-13 13:33:07,115 TRACE [org.apereo.cas.support.saml.web.view.Saml10SuccessResponseView] - <Rendering view with name 'scopedTarget.casSamlServiceSuccessView' with model {assertion=org.apereo.cas.authentication.DefaultAuthentication@a5921729:https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check, service=https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check, pgtIou=null, org.springframework.validation.BindingResult.assertion=org.springframework.validation.BeanPropertyBindingResult: 0 errors, org.springframework.validation.BindingResult.service=org.springframework.validation.BeanPropertyBindingResult: 0 errors} and static attributes {}>
2017-02-13 13:33:07,115 TRACE [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Could not obtain the saml request body from the http request>
java.io.IOException: Stream closed
        at org.apache.catalina.connector.InputBuffer.mark(InputBuffer.java:514) ~[catalina.jar:8.5.11]
        at org.apache.catalina.connector.CoyoteReader.mark(CoyoteReader.java:135) ~[catalina.jar:8.5.11]
        at org.apache.catalina.connector.CoyoteReader.readLine(CoyoteReader.java:161) ~[catalina.jar:8.5.11]
        at org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory.getRequestBody(SamlServiceFactory.java:115) ~[cas-server-support-saml-5.0.2.jar:5.0.2]
        at org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory.createService(SamlServiceFactory.java:33) ~[cas-server-support-saml-5.0.2.jar:5.0.2]
        at org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory.createService(SamlServiceFactory.java:17) ~[cas-server-support-saml-5.0.2.jar:5.0.2]
        at org.apereo.cas.web.support.DefaultArgumentExtractor.lambda$extractServiceInternal$0(DefaultArgumentExtractor.java:46) ~[cas-server-core-web-5.0.2.jar:5.0.2]
        at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) ~[?:1.8.0_121]
        at java.util.ArrayList$ArrayListSpliterator.tryAdvance(ArrayList.java:1351) ~[?:1.8.0_121]
        at java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126) ~[?:1.8.0_121]
        at java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:498) ~[?:1.8.0_121]
        at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:485) ~[?:1.8.0_121]
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:1.8.0_121]
        at java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:152) ~[?:1.8.0_121]
        at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:1.8.0_121]
        at java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:464) ~[?:1.8.0_121]
        at org.apereo.cas.web.support.DefaultArgumentExtractor.extractServiceInternal(DefaultArgumentExtractor.java:52) ~[cas-server-core-web-5.0.2.jar:5.0.2]
        at org.apereo.cas.web.support.AbstractArgumentExtractor.extractService(AbstractArgumentExtractor.java:56) ~[cas-server-core-web-5.0.2.jar:5.0.2]
        at org.apereo.cas.support.saml.web.view.AbstractSaml10ResponseView.renderMergedOutputModel(AbstractSaml10ResponseView.java:88) ~[cas-server-support-saml-5.0.2.jar:5.0.2]
        at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:303) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_121]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_121]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_121]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_121]
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) ~[spring-aop-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at com.sun.proxy.$Proxy93.render(Unknown Source) ~[?:?]
        at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1257) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1037) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:980) ~[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.doPost(FrameworkServlet.java:872) ~[spring-webmvc-4.3.4.RELEASE.jar:4.3.4.RELEASE]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:648) ~[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:729) ~[servlet-api.jar:?]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) ~[tomcat-websocket.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55) ~[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.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        at org.apereo.cas.web.support.CurrentCredentialsAndAuthenticationClearingFilter.doFilter(CurrentCredentialsAndAuthenticationClearingFilter.java:28) ~[cas-server-core-web-5.0.2.jar:5.0.2]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        at org.apereo.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:64) ~[inspektr-common-1.6.GA.jar:1.6.GA]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        at org.apereo.cas.logging.web.ThreadContextMDCServletFilter.doFilter(ThreadContextMDCServletFilter.java:90) ~[cas-server-core-logging-5.0.2.jar:5.0.2]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        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:192) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[catalina.jar:8.5.11]
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:591) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) ~[catalina.jar:8.5.11]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) ~[catalina.jar:8.5.11]
        at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624) ~[catalina.jar:8.5.11]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) ~[catalina.jar:8.5.11]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349) ~[catalina.jar:8.5.11]
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:783) ~[tomcat-coyote.jar:8.5.11]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-coyote.jar:8.5.11]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:798) ~[tomcat-coyote.jar:8.5.11]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1434) ~[tomcat-coyote.jar:8.5.11]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-coyote.jar:8.5.11]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_121]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_121]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-util.jar:8.5.11]
        at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
2017-02-13 13:33:07,115 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Request Body: null>
2017-02-13 13:33:07,116 DEBUG [org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory] - <Extracted ArtifactId: null. extracted Request Id: null>
2017-02-13 13:33:07,116 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check based on org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory@13670417>
2017-02-13 13:33:07,116 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check based on org.apereo.cas.support.saml.authentication.principal.SamlServiceFactory@13670417>
2017-02-13 13:33:07,116 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.support.saml.authentication.principal.SamlService for: https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,116 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.support.saml.authentication.principal.SamlService for: https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,117 DEBUG [org.apereo.cas.support.saml.web.view.Saml10SuccessResponseView] - <Using xessdev1.xxx.edu as the recipient of the SAML response for https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check>
2017-02-13 13:33:07,119 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting null obj to empty collection>
2017-02-13 13:33:07,121 TRACE [org.apereo.cas.support.saml.web.view.Saml10SuccessResponseView] - <[credential] is not available and will not be released to the validation response.>
2017-02-13 13:33:07,121 TRACE [org.apereo.cas.support.saml.web.view.Saml10SuccessResponseView] - <[proxyGrantingTicket] is not available and will not be released to the validation response.>
2017-02-13 13:33:07,121 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <Starting to encode attributes for release to service [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check]>
2017-02-13 13:33:07,122 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[credential] is not available as a cached model attribute to encrypt...>
2017-02-13 13:33:07,122 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[proxyGrantingTicket] is not available as a cached model attribute to encrypt...>
2017-02-13 13:33:07,122 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <Sanitizing attribute names in preparation of the final validation response>
2017-02-13 13:33:07,122 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[3] Encoded attributes are available for release to [https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check]>
2017-02-13 13:33:07,163 DEBUG [org.apereo.cas.support.saml.SamlUtils] - <Logging [org.opensaml.saml.saml1.core.impl.ResponseImpl]
<?xml version="1.0" encoding="UTF-8"?><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" InResponseTo="xessdev1.xxx.edu" IssueInstant="2017-02-13T18:33:07.119Z" MajorVersion="1" MinorVersion="1" ResponseID="_d03cf0717e2ce143eba3e54c6f3e3f06"><saml1p:Status><saml1p:StatusCode Value="saml1p:Success"/></saml1p:Status><saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_29780d6f9d6c744904e567f6b9ea68a4" IssueInstant="2017-02-13T18:33:07.119Z" Issuer="localhost" MajorVersion="1" MinorVersion="1"><saml1:Conditions NotBefore="2017-02-13T18:33:07.119Z" NotOnOrAfter="2017-02-13T18:33:37.119Z"><saml1:AudienceRestrictionCondition><saml1:Audience>https://xessdev1.xxx.edu:8446/PRDCStudentFacultyGradeEntry/j_spring_cas_security_check</saml1:Audience></saml1:AudienceRestrictionCondition></saml1:Conditions><saml1:AuthenticationStatement AuthenticationInstant="2017-02-13T18:33:07.017Z" AuthenticationMethod="urn:oasis:names:tc:SAML:1.0:am:unspecified"><saml1:Subject><saml1:NameIdentifier>jsmith</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:artifact</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject></saml1:AuthenticationStatement><saml1:AttributeStatement><saml1:Subject><saml1:NameIdentifier>jsmith</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:artifact</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject><saml1:Attribute AttributeName="sn" AttributeNamespace="http://www.ja-sig.org/products/cas/"><saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">Smith</saml1:AttributeValue></saml1:Attribute><saml1:Attribute AttributeName="authenticationMethod" AttributeNamespace="http://www.ja-sig.org/products/cas/"><saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">LdapAuthenticationHandler</saml1:AttributeValue></saml1:Attribute><saml1:Attribute AttributeName="successfulAuthenticationHandlers" AttributeNamespace="http://www.ja-sig.org/products/cas/"><saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">LdapAuthenticationHandler</saml1:AttributeValue></saml1:Attribute></saml1:AttributeStatement></saml1:Assertion></saml1p:Response>>
2017-02-13 13:33:07,168 TRACE [org.springframework.web.servlet.DispatcherServlet] - <Cleared thread-bound request context: org.apache.catalina.connector.RequestFacade@11051950>
2017-02-13 13:33:07,168 DEBUG [org.springframework.web.servlet.DispatcherServlet] - <Successfully completed request>


To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+unsubscribe@apereo.org.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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+unsubscribe@apereo.org.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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/CACjUCorT7WJHiN0DWRKJPHhwRfK8b1g%2BNg2NxGTvAewFCTQn4g%40mail.gmail.com.

Dmitriy Kopylenko

unread,
Feb 13, 2017, 2:05:52 PM2/13/17
to cas-...@apereo.org
Try deleting this block:

##
# LDAP Attributes
#
cas.authn.attributeRepository.ldap.ldapUrl=ldaps://xxx
cas.authn.attributeRepository.ldap.useSsl=true
cas.authn.attributeRepository.ldap.useStartTls=false
cas.authn.attributeRepository.ldap.connectTimeout=5000
cas.authn.attributeRepository.ldap.baseDn=ou=People,o=xxx
cas.authn.attributeRepository.ldap.userFilter=uid={user}
cas.authn.attributeRepository.ldap.subtreeSearch=true
cas.authn.attributeRepository.ldap.bindDn=xxx
cas.authn.attributeRepository.ldap.bindCredential=xxx

##
# Person Directory / Attributes
#
cas.personDirectory.principalAttribute=uid
cas.personDirectory.returnNull=false

You don’t need it if you are directly retrieving attributes as part of authentication transaction i.e. cas.authn.ldap[0].principalAttributeList=sn,cn:commonName,gn:givenName,xxxPersonUDCID:UDC_IDENTIFIER

Also verify that those attributes actually exist in the directory. I saw in the log that you pasted that it was only able to return the sn attr.

D.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/etPan.58a2038a.24a0d8df.346%40unicon.net.

Rob

unread,
Feb 13, 2017, 2:46:42 PM2/13/17
to cas-...@apereo.org
That helped!! Thank you very much, I am now getting back 

<saml1:Attribute AttributeName="uid" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">jsmith</saml1:AttributeValue>
</saml1:Attribute>
<saml1:Attribute AttributeName="sn" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">Smith</saml1:AttributeValue>
</saml1:Attribute>
<saml1:Attribute AttributeName="authenticationMethod" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">LdapAuthenticationHandler</saml1:AttributeValue>
</saml1:Attribute>
<saml1:Attribute AttributeName="givenName" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">Joe</saml1:AttributeValue>
</saml1:Attribute>
<saml1:Attribute AttributeName="successfulAuthenticationHandlers" AttributeNamespace="http://www.ja-sig.org/products/cas/">
<saml1:AttributeValue xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:type="xsd:string">LdapAuthenticationHandler</saml1:AttributeValue>
</saml1:Attribute>

I also cleaned up the bad entries. Checking with the LDAP group to see if I have access to the other attributes when I come in anonymous as the principal rather than an LDAP look up account.

Thank you very much for your help!!!


2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-2-FIbDHyBrdFS0kM03oa7HKSEEudMqCJzJt6MtSiBuGAqIwdZ7ns-vml01006@10.48.6.120@Mozilla/5.0 (Windows NT 10.0; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0]>
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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.
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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+unsubscribe@apereo.org.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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+unsubscribe@apereo.org.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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/CACjUCoq5Oa1zwJFJK0O3v43V2%2B1XOyQWgWG%2BPeq%2Bi8J4%2BJywnw%40mail.gmail.com.

Rob

unread,
Feb 13, 2017, 3:25:22 PM2/13/17
to cas-...@apereo.org
Thanks so much for your help Dmitiry,

It turns out I needed the LDAP attribute block since I could not load the additional attributes with the principal login account. So by adding back the LDAP lookup account and removing the cas.authn.ldap[0].principalAttributeList from the auth attributes I was able to finally get the correct combination for the right attributes. 

Again thanks for your help, I would not have solved this without it!!  


2017-02-13 13:33:07,029 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-2-FIbDHyBrdFS0kM03oa7HKSEEudMqCJzJt6MtSiBuGAqIwdZ7ns-vml01006@10.48.6.120@Mozilla/5.0 (Windows NT 10.0; WOW64; rv:51.0) Gecko/20100101 Firefox/51.0]>
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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.
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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+unsubscribe@apereo.org.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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+unsubscribe@apereo.org.

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
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/CACjUCoqTYuoV2dCir%3DpLqahtpiG52%2BmJY-j2erJ_WembFMA1gQ%40mail.gmail.com.
Reply all
Reply to author
Forward
0 new messages