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.
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,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] - <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,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.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,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.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.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.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.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,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 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 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 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.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.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 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.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] - <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,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.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,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,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,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>