[cas-user] CAS 4.2.x Password Policy Active Directory (ldaptive)

79 views
Skip to first unread message

Brandon Martin

unread,
Oct 25, 2016, 9:51:29 AM10/25/16
to CAS Community
Greetings,

After a little bit of work I was able to get successful AD authentication on CAS 4.2.6. Yay!

I've implemented the password enforcement configs from here: https://apereo.github.io/cas/4.2.x/installation/LDAP-Authentication.html 

I'm not seeing any changes, possibly I'm missing a config. When I set a user to needs password reset in AD (PasswordExpired AD Attribute), I simply get "AUTHENTICATION_FAILED" in the response.

In the ldaptive logs, I see this: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903CF, comment: AcceptSecurityContext error, data 773, v2580]
I also see the user's dn, and attributes in the log.

Looking up error code 49, it's an invalid credentials response. 

We have our own in house developed password reset tool, so CAS just needs to be able to display the errors with a button to navigate to the reset tool. I have the casMustChangePassView.jsp where I'd add our button.

One thing that comes to mind is if CAS/ldaptive doesn't know what attributes to read from AD to determine the password policy errors, but I'm unsure what they would be looking for/need.

DeployerConfigContext.xml

    <alias name="ldapPasswordPolicyConfiguration" alias="passwordPolicyConfiguration" />
 
    <bean id="ldapAuthenticationHandler"
       class="org.jasig.cas.authentication.LdapAuthenticationHandler"
       p:principalIdAttribute="sAMAccountName"
       p:passwordPolicyConfiguration-ref="passwordPolicyConfiguration"
       c:authenticator-ref="authenticator" >
       <property name="principalAttributeMap">
          <map>
              <entry key="sAMAccountName" value="uid"/>
              <entry key="displayName" value="displayName"/>
              <entry key="mail" value="mail"/>
              <entry key="memberOf" value="memberOf"/>
              <entry key="employeeId" value="distinguishedName"/>
              <entry key="sn" value="sn"/>
              <entry key="givenName" value="givenName"/>
              <entry key="telephoneNumber" value="telephoneNumber"/>
          </map>
        </property>
    </bean>
 
    <ldaptive:bind-search-authenticator id="authenticator"
            ldapUrl="${ldap.url}"
            baseDn="${ldap.baseDn}"
            userFilter="${ldap.searchFilter}"
            bindDn="${ldap.managerDn}"
            bindCredential="${ldap.managerPassword}"
            allowMultipleDns="${ldap.allowMultipleDns:false}"
            connectTimeout="${ldap.connectTimeout}"
            validateOnCheckOut="${ldap.pool.validateOnCheckout}"
            failFastInitialize="true"
            blockWaitTime="${ldap.pool.blockWaitTime}"
            idleTime="${ldap.pool.idleTime}"
            maxPoolSize="${ldap.pool.maxSize}"
            minPoolSize="${ldap.pool.minSize}"
            validatePeriodically="${ldap.pool.validatePeriodically}"
            validatePeriod="${ldap.pool.validatePeriod}"
            prunePeriod="${ldap.pool.prunePeriod}"
            useSSL="${ldap.use.ssl:false}"
            subtreeSearch="true"
            useStartTLS="${ldap.useStartTLS}"
            usePasswordPolicy="${ldap.usePpolicy:true}" />

cas.properties:

password.policy.warningDays=30

# URL to which the user will be redirected to change the password.

password.policy.warn.attribute.value=attributeValue
password.policy.warn.display.matched=true

ldap.usePpolicy=true


Let me know if I should post the full ldaptive logs

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/9b78a140-c858-4202-8a79-006038542fcd%40apereo.org.

Misagh Moayyed

unread,
Oct 25, 2016, 2:48:02 PM10/25/16
to CAS Community
Share CAS logs please, at DEBUG.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/5c703f6c-16e2-4d7f-b3d6-36919f01235c%40apereo.org.

Brandon Martin

unread,
Oct 25, 2016, 5:13:13 PM10/25/16
to CAS Community
Okay here we go:

Following the logs, I successfully authenticate, then change the attribute PasswordExpired = True in AD, where another attempt at login fails.
[INFO] Scanning for projects...
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building cas-overlay 1.0
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- maven-clean-plugin:2.5:clean (default-clean) @ cas-overlay ---
[INFO] Deleting /cas-overlay/target
[INFO] 
[INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ cas-overlay ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /cas-overlay/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:compile (default-compile) @ cas-overlay ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ cas-overlay ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /cas-overlay/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:testCompile (default-testCompile) @ cas-overlay ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-surefire-plugin:2.12.4:test (default-test) @ cas-overlay ---
[INFO] No tests to run.
[INFO] 
[INFO] --- maven-war-plugin:2.6:war (default-war) @ cas-overlay ---
[INFO] Packaging webapp
[INFO] Assembling webapp [cas-overlay] in [/cas-overlay/target/cas]
[INFO] Processing war project
[INFO] Copying webapp resources [/cas-overlay/src/main/webapp]
[INFO] Processing overlay [ id org.jasig.cas:cas-server-webapp]
[INFO] Webapp assembled in [2636 msecs]
[INFO] Building war: /cas-overlay/target/cas.war
[INFO] 
[INFO] >>> jetty-maven-plugin:9.3.6.v20151106:run-forked (default-cli) > test-compile @ cas-overlay >>>
[INFO] 
[INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ cas-overlay ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /cas-overlay/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:compile (default-compile) @ cas-overlay ---
[INFO] No sources to compile
[INFO] 
[INFO] --- maven-resources-plugin:2.6:testResources (default-testResources) @ cas-overlay ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /cas-overlay/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:3.3:testCompile (default-testCompile) @ cas-overlay ---
[INFO] No sources to compile
[INFO] 
[INFO] <<< jetty-maven-plugin:9.3.6.v20151106:run-forked (default-cli) < test-compile @ cas-overlay <<<
[INFO] 
[INFO] --- jetty-maven-plugin:9.3.6.v20151106:run-forked (default-cli) @ cas-overlay ---
[INFO] Logging initialized @14540ms
[INFO] Configuring Jetty for project: cas-overlay
[INFO] webAppSourceDirectory not set. Trying src/main/webapp
[INFO] Reload Mechanic: automatic
[INFO] Classes directory /cas-overlay/target/classes does not exist
[INFO] Context path = /cas
[INFO] Tmp directory = /cas-overlay/target/tmp
[INFO] Web defaults = org/eclipse/jetty/webapp/webdefault.xml
[INFO] Web overrides = /cas-overlay/etc/jetty/web.xml
[INFO] Dependent war artifact org.jasig.cas:cas-server-webapp:war:4.2.6
[INFO] web.xml file = null
[INFO] Webapp directory = /cas-overlay/src/main/webapp
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/root/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.6.2/log4j-slf4j-impl-2.6.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/cas-overlay/target/tmp/cas-server-webapp-4_2_6_war1/WEB-INF/lib/cas-server-core-logging-4.2.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/cas-overlay/target/tmp/cas-server-webapp-4_2_6_war1/WEB-INF/lib/log4j-slf4j-impl-2.6.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console.
[INFO] Quickstart generating
[INFO] Started o.e.j.m.p.JettyWebAppContext@3c0e00a8{/cas,[file:///cas-overlay/src/main/webapp/, file:///cas-overlay/target/tmp/cas-server-webapp-4_2_6_war1/],AVAILABLE}{file:///cas-overlay/src/main/webapp/}
[INFO] Stopped o.e.j.m.p.JettyWebAppContext@3c0e00a8{/cas,file:///cas-overlay/src/main/webapp/,UNAVAILABLE}{file:///cas-overlay/src/main/webapp/}
[INFO] Forked process starting
[STDOUT] Listening for transport dt_socket at address: 5000
[STDERR] 2016-10-25 20:58:24.025:INFO::main: Logging initialized @13271ms
[STDERR] 2016-10-25 20:58:24.404:INFO:oejmp.Starter:main: Started Jetty Server
[STDERR] 2016-10-25 20:58:24.412:INFO:oejs.Server:main: jetty-9.3.6.v20151106
[STDERR] SLF4J: Class path contains multiple SLF4J bindings.
[STDERR] SLF4J: Found binding in [jar:file:/root/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.6.2/log4j-slf4j-impl-2.6.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
[STDERR] SLF4J: Found binding in [jar:file:/cas-overlay/target/tmp/cas-server-webapp-4_2_6_war1/WEB-INF/lib/cas-server-core-logging-4.2.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
[STDERR] SLF4J: Found binding in [jar:file:/cas-overlay/target/tmp/cas-server-webapp-4_2_6_war1/WEB-INF/lib/log4j-slf4j-impl-2.6.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
[STDERR] SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
[STDERR] SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
[STDERR] 2016-10-25 20:58:27.656:INFO:/cas:main: 2 Spring WebApplicationInitializers detected on classpath
[STDOUT] 2016-10-25 20:58:27,686 INFO [org.jasig.cas.support.saml.SamlServletContextListener] - <Starting up servlet application context...>
[STDOUT] 2016-10-25 20:58:27,691 INFO [org.jasig.cas.support.saml.SamlGoogleAppsServletContextListener] - <Starting up servlet application context...>
[STDOUT] 2016-10-25 20:58:27,786 INFO [org.jasig.cas.CasEnvironmentContextListener] - <
[STDOUT] ******************** Welcome to CAS *******************
[STDOUT] CAS Version: 4.2.6
[STDOUT] Build Date/Time: 2016-09-28T12:16:24.000Z
[STDOUT] Java Home: /opt/jdk1.8.0_65/jre
[STDOUT] Java Vendor: Oracle Corporation
[STDOUT] Java Version: 1.8.0_65
[STDOUT] OS Architecture: amd64
[STDOUT] OS Name: Linux
[STDOUT] OS Version: 4.4.20-moby
[STDOUT] *******************************************************
[STDOUT] >
[STDERR] 2016-10-25 20:58:27.845:INFO:/cas:main: Initializing Spring root WebApplicationContext
[STDOUT] 2016-10-25 20:58:33,824 WARN [org.jasig.cas.util.NoOpCipherExecutor] - <[org.jasig.cas.util.NoOpCipherExecutor] does no encryption and may NOT be safe in a production environment. Consider using other choices, such as [org.jasig.cas.util.BaseStringCipherExecutor] that handle encryption, signing and verification of all appropriate values.>
[STDOUT] 2016-10-25 20:58:34,634 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JsonServiceRegistryDao.>
[STDOUT] 2016-10-25 20:58:34,953 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Services manager will reload service definitions every 60 seconds>
[STDOUT] 2016-10-25 20:58:36,848 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <beginning pool initialization for [org.ldaptive.pool.BlockingConnectionPool@365212068::name=search-pool, poolConfig=[org.ldaptive.pool.PoolConfig@874079440::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@1370856792::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@3522572::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1826086004::provider=org.ldaptive.provider.jndi.JndiProvider@6d695ec4, config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=0, activeCount=0]>
[STDOUT] 2016-10-25 20:58:36,866 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <checking connection pool size >= 3 for [org.ldaptive.pool.BlockingConnectionPool@365212068::name=search-pool, poolConfig=[org.ldaptive.pool.PoolConfig@874079440::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@1370856792::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@3522572::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1826086004::provider=org.ldaptive.provider.jndi.JndiProvider@6d695ec4, config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=0, activeCount=0]>
[STDOUT] 2016-10-25 20:58:36,953 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@870869323::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1338446903::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1975607158::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b10f60e]>
[STDOUT] 2016-10-25 20:58:36,986 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@548828006::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@870869323::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1338446903::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1975607158::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1b10f60e]>
[STDOUT] 2016-10-25 20:58:36,995 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@4fc7f23e>
[STDOUT] 2016-10-25 20:58:37,015 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1474657733::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1538955593::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@342907384::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@744fb110]>
[STDOUT] 2016-10-25 20:58:37,032 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@137945353::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@1474657733::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1538955593::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@342907384::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@744fb110]>
[STDOUT] 2016-10-25 20:58:37,036 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@5bbb7750>
[STDOUT] 2016-10-25 20:58:37,057 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@122110358::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 20:58:37,075 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1789503803::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@122110358::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 20:58:37,081 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@11ef4526>
[STDOUT] 2016-10-25 20:58:37,082 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <initialized available queue: [org.ldaptive.pool.Queue@136183278::queueType=LIFO, queue=[org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@11ef4526, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@5bbb7750, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@4fc7f23e]]>
[STDOUT] 2016-10-25 20:58:37,092 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <prune pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@365212068::name=search-pool, poolConfig=[org.ldaptive.pool.PoolConfig@874079440::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@1370856792::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@3522572::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1826086004::provider=org.ldaptive.provider.jndi.JndiProvider@6d695ec4, config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=3, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,111 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <validate pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@365212068::name=search-pool, poolConfig=[org.ldaptive.pool.PoolConfig@874079440::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@1370856792::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@3522572::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1826086004::provider=org.ldaptive.provider.jndi.JndiProvider@6d695ec4, config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=3, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,119 INFO [org.ldaptive.pool.BlockingConnectionPool] - <pool initialized [org.ldaptive.pool.BlockingConnectionPool@365212068::name=search-pool, poolConfig=[org.ldaptive.pool.PoolConfig@874079440::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@1370856792::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@3522572::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1826086004::provider=org.ldaptive.provider.jndi.JndiProvider@6d695ec4, config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=true, availableCount=3, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,367 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <beginning pool initialization for [org.ldaptive.pool.BlockingConnectionPool@1980783296::name=bind-pool, poolConfig=[org.ldaptive.pool.PoolConfig@906341142::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@818618939::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@617662116::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1357008548::provider=org.ldaptive.provider.jndi.JndiProvider@4ba402b5, config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=0, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,373 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <checking connection pool size >= 3 for [org.ldaptive.pool.BlockingConnectionPool@1980783296::name=bind-pool, poolConfig=[org.ldaptive.pool.PoolConfig@906341142::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@818618939::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@617662116::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1357008548::provider=org.ldaptive.provider.jndi.JndiProvider@4ba402b5, config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=0, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,394 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1107678672::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@702531215::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@839624607::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@8c18bde]>
[STDOUT] 2016-10-25 20:58:37,412 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1729753606::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@1107678672::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@702531215::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@839624607::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@8c18bde]>
[STDOUT] 2016-10-25 20:58:37,419 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@29e0a496>
[STDOUT] 2016-10-25 20:58:37,441 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@95295146::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@877266522::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@810673270::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1870b9b8]>
[STDOUT] 2016-10-25 20:58:37,473 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1839130458::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@95295146::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@877266522::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@810673270::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@1870b9b8]>
[STDOUT] 2016-10-25 20:58:37,474 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@344ae461>
[STDOUT] 2016-10-25 20:58:37,783 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@159536229::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 20:58:37,799 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@720075852::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@159536229::bindDn=admin...@peninsula.wednet.edu, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 20:58:37,801 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@36d0417e>
[STDOUT] 2016-10-25 20:58:37,802 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <initialized available queue: [org.ldaptive.pool.Queue@1743939261::queueType=LIFO, queue=[org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@36d0417e, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@344ae461, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@29e0a496]]>
[STDOUT] 2016-10-25 20:58:37,805 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <prune pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@1980783296::name=bind-pool, poolConfig=[org.ldaptive.pool.PoolConfig@906341142::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@818618939::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@617662116::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1357008548::provider=org.ldaptive.provider.jndi.JndiProvider@4ba402b5, config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=3, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,809 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <validate pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@1980783296::name=bind-pool, poolConfig=[org.ldaptive.pool.PoolConfig@906341142::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@818618939::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@617662116::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1357008548::provider=org.ldaptive.provider.jndi.JndiProvider@4ba402b5, config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=false, availableCount=3, activeCount=0]>
[STDOUT] 2016-10-25 20:58:37,817 INFO [org.ldaptive.pool.BlockingConnectionPool] - <pool initialized [org.ldaptive.pool.BlockingConnectionPool@1980783296::name=bind-pool, poolConfig=[org.ldaptive.pool.PoolConfig@906341142::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=300], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@818618939::searchRequest=[org.ldaptive.SearchRequest@6117248::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, 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@617662116::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1357008548::provider=org.ldaptive.provider.jndi.JndiProvider@4ba402b5, config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]]], initialized=true, availableCount=3, activeCount=0]>
[STDOUT] 2016-10-25 20:58:38,608 INFO [org.jasig.cas.support.saml.SamlGoogleAppsServletContextListener] - <Initializing SamlGoogleAppsServletContextListener root application context>
[STDOUT] 2016-10-25 20:58:38,632 INFO [org.jasig.cas.support.saml.SamlGoogleAppsServletContextListener] - <Initialized SamlGoogleAppsServletContextListener root application context successfully>
[STDOUT] 2016-10-25 20:58:38,632 INFO [org.jasig.cas.support.saml.SamlGoogleAppsServletContextListener] - <Initializing SamlGoogleAppsServletContextListener servlet application context>
[STDOUT] 2016-10-25 20:58:38,633 INFO [org.jasig.cas.support.saml.SamlGoogleAppsServletContextListener] - <Initialized SamlGoogleAppsServletContextListener servlet application context successfully>
[STDOUT] 2016-10-25 20:58:45,146 INFO [org.jasig.cas.support.saml.SamlServletContextListener] - <Initializing SamlServletContextListener root application context>
[STDOUT] 2016-10-25 20:58:45,149 INFO [org.jasig.cas.support.saml.SamlServletContextListener] - <Initialized SamlServletContextListener root application context successfully>
[STDOUT] 2016-10-25 20:58:45,152 INFO [org.jasig.cas.support.saml.SamlServletContextListener] - <Initializing SamlServletContextListener servlet application context>
[STDOUT] 2016-10-25 20:58:46,984 ERROR [org.jasig.cas.support.saml.SamlServletContextListener] - <Error creating bean with name 'handlerMappingC' defined in ServletContext resource [/WEB-INF/spring-configuration/applicationContext.xml]: Initialization of bean failed; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'metricsController' defined in ServletContext resource [/WEB-INF/spring-configuration/applicationContext.xml]: Invocation of init method failed; nested exception is javax.servlet.ServletException: Couldn't find a MetricRegistry instance.>
[STDOUT] org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'handlerMappingC' defined in ServletContext resource [/WEB-INF/spring-configuration/applicationContext.xml]: Initialization of bean failed; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'metricsController' defined in ServletContext resource [/WEB-INF/spring-configuration/applicationContext.xml]: Invocation of init method failed; nested exception is javax.servlet.ServletException: Couldn't find a MetricRegistry instance.
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:553) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1060) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.jasig.cas.web.AbstractServletContextInitializer.getCasServletHandlerMapping(AbstractServletContextInitializer.java:194) ~[cas-server-core-web-4.2.6.jar:4.2.6]
[STDOUT] at org.jasig.cas.web.AbstractServletContextInitializer.addControllerToCasServletHandlerMapping(AbstractServletContextInitializer.java:206) ~[cas-server-core-web-4.2.6.jar:4.2.6]
[STDOUT] at org.jasig.cas.support.saml.SamlServletContextListener.initializeServletApplicationContext(SamlServletContextListener.java:60) ~[cas-server-support-saml-4.2.6.jar:4.2.6]
[STDOUT] at org.jasig.cas.web.AbstractServletContextInitializer.setApplicationContext(AbstractServletContextInitializer.java:111) ~[cas-server-core-web-4.2.6.jar:4.2.6]
[STDOUT] at org.springframework.context.support.ApplicationContextAwareProcessor.invokeAwareInterfaces(ApplicationContextAwareProcessor.java:119) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationContextAwareProcessor.postProcessBeforeInitialization(ApplicationContextAwareProcessor.java:94) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:408) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1574) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:778) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:839) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:538) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:444) ~[spring-web-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:326) ~[spring-web-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:107) ~[spring-web-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:835) ~[?:?]
[STDOUT] at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:530) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:808) ~[?:?]
[STDOUT] at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:342) ~[?:?]
[STDOUT] at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1379) ~[?:?]
[STDOUT] at org.eclipse.jetty.maven.plugin.JettyWebAppContext.startWebapp(JettyWebAppContext.java:323) ~[?:?]
[STDOUT] at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1341) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:772) ~[?:?]
[STDOUT] at org.eclipse.jetty.servlet.ServletContextHandler.doStart(ServletContextHandler.java:259) ~[?:?]
[STDOUT] at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:517) ~[?:?]
[STDOUT] at org.eclipse.jetty.maven.plugin.JettyWebAppContext.doStart(JettyWebAppContext.java:398) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.handler.ContextHandlerCollection.doStart(ContextHandlerCollection.java:161) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.Server.start(Server.java:405) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:106) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61) ~[?:?]
[STDOUT] at org.eclipse.jetty.server.Server.doStart(Server.java:372) ~[?:?]
[STDOUT] at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) ~[?:?]
[STDOUT] at org.eclipse.jetty.maven.plugin.Starter.run(Starter.java:370) ~[?:?]
[STDOUT] at org.eclipse.jetty.maven.plugin.Starter.main(Starter.java:468) ~[?:?]
[STDOUT] Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'metricsController' defined in ServletContext resource [/WEB-INF/spring-configuration/applicationContext.xml]: Invocation of init method failed; nested exception is javax.servlet.ServletException: Couldn't find a MetricRegistry instance.
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1582) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1054) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.servlet.handler.AbstractUrlHandlerMapping.registerHandler(AbstractUrlHandlerMapping.java:313) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.servlet.handler.SimpleUrlHandlerMapping.registerHandlers(SimpleUrlHandlerMapping.java:128) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.servlet.handler.SimpleUrlHandlerMapping.initApplicationContext(SimpleUrlHandlerMapping.java:103) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationObjectSupport.initApplicationContext(ApplicationObjectSupport.java:120) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.context.support.WebApplicationObjectSupport.initApplicationContext(WebApplicationObjectSupport.java:76) ~[spring-web-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationObjectSupport.setApplicationContext(ApplicationObjectSupport.java:74) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationContextAwareProcessor.invokeAwareInterfaces(ApplicationContextAwareProcessor.java:119) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationContextAwareProcessor.postProcessBeforeInitialization(ApplicationContextAwareProcessor.java:94) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:408) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1574) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] ... 55 more
[STDOUT] Caused by: javax.servlet.ServletException: Couldn't find a MetricRegistry instance.
[STDOUT] at com.codahale.metrics.servlets.MetricsServlet.init(MetricsServlet.java:139) ~[metrics-servlets-3.1.2.jar:3.1.2]
[STDOUT] at org.springframework.web.servlet.mvc.ServletWrappingController.afterPropertiesSet(ServletWrappingController.java:140) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1641) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1578) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1054) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.servlet.handler.AbstractUrlHandlerMapping.registerHandler(AbstractUrlHandlerMapping.java:313) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.servlet.handler.SimpleUrlHandlerMapping.registerHandlers(SimpleUrlHandlerMapping.java:128) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.servlet.handler.SimpleUrlHandlerMapping.initApplicationContext(SimpleUrlHandlerMapping.java:103) ~[spring-webmvc-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationObjectSupport.initApplicationContext(ApplicationObjectSupport.java:120) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.web.context.support.WebApplicationObjectSupport.initApplicationContext(WebApplicationObjectSupport.java:76) ~[spring-web-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationObjectSupport.setApplicationContext(ApplicationObjectSupport.java:74) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationContextAwareProcessor.invokeAwareInterfaces(ApplicationContextAwareProcessor.java:119) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.context.support.ApplicationContextAwareProcessor.postProcessBeforeInitialization(ApplicationContextAwareProcessor.java:94) ~[spring-context-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsBeforeInitialization(AbstractAutowireCapableBeanFactory.java:408) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1574) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:545) ~[spring-beans-4.2.8.RELEASE.jar:4.2.8.RELEASE]
[STDOUT] ... 55 more
[STDOUT] 2016-10-25 20:58:49,180 INFO [org.jasig.cas.ticket.registry.TicketRegistryCleaner] - <Preparing to schedule job to clean up after tickets...>
[STDOUT] 2016-10-25 20:58:49,180 INFO [org.jasig.cas.ticket.registry.TicketRegistryCleaner] - <TicketRegistryCleaner will clean tickets every 2 minutes>
[STDOUT] 2016-10-25 20:58:52,689 INFO [org.jasig.cas.support.saml.OpenSamlConfigBean] - <Initializing OpenSaml configuration...>
[STDOUT] 2016-10-25 20:58:59,829 INFO [org.jasig.cas.CasEnvironmentContextListener] - <[jetty/9.3.6.v20151106] has loaded the CAS servlet application context: Root WebApplicationContext: startup date [Tue Oct 25 20:58:27 UTC 2016]; root of context hierarchy>
[STDERR] 2016-10-25 20:59:00.084:INFO:/cas:main: Initializing Spring FrameworkServlet 'cas'
[STDERR] 2016-10-25 20:59:02.299:INFO:oejsh.ContextHandler:main: Started o.e.j.m.p.JettyWebAppContext@65d6b83b{/cas,[file:///cas-overlay/src/main/webapp/, file:///cas-overlay/target/tmp/cas-server-webapp-4_2_6_war1/],AVAILABLE}
[STDERR] 2016-10-25 20:59:02.320:INFO:oejs.ServerConnector:main: Started ServerConnector@3f9167f7{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}
[STDERR] 2016-10-25 20:59:02.329:INFO:oejus.SslContextFactory:main: x509=X509@579847d7(tomcat,h=[],w=[]) for SslContextFactory@156b3428(file:///etc/cas/jetty/thekeystore,file:///etc/cas/jetty/thekeystore)
[STDERR] 2016-10-25 20:59:02.443:INFO:oejs.ServerConnector:main: Started ServerConnector@7abe70f7{SSL,[ssl, http/1.1]}{0.0.0.0:8443}
[STDOUT] -DQ5WLBKUQ1WV
[STDERR] 2016-10-25 20:59:02.444:INFO:oejs.Server:main: Started @51694ms
[STDOUT] 2016-10-25 20:59:09,247 INFO [org.jasig.cas.ticket.registry.TicketRegistryCleaner] - <Beginning ticket cleanup...>
[STDOUT] 2016-10-25 20:59:09,251 INFO [org.jasig.cas.ticket.registry.TicketRegistryCleaner] - <0 expired tickets found and removed.>
[STDOUT] 2016-10-25 20:59:50,013 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Reloading registered services.>
[STDOUT] 2016-10-25 20:59:50,077 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JsonServiceRegistryDao.>
[STDOUT] 2016-10-25 21:00:36,178 INFO [org.jasig.cas.web.flow.InitialFlowSetupAction] - <Setting path for cookies for warn cookie generator to: /cas/ >
[STDOUT] 2016-10-25 21:00:36,178 INFO [org.jasig.cas.web.flow.InitialFlowSetupAction] - <Setting path for cookies for TGC cookie generator to: /cas/ >
[STDOUT] 2016-10-25 21:00:45,432 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolve user=username>
[STDOUT] 2016-10-25 21:00:45,440 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <searching for DN using userFilter>
[STDOUT] 2016-10-25 21:00:45,458 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1737167252::baseDn=ou=Users,ou=PSD,dc=Peninsula,dc=wednet,dc=edu, searchFilter=[org.ldaptive.SearchFilter@1615263833::filter=(sAMAccountName={user}), parameters={user=username}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, 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@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 21:00:45,545 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@985439959::result=[org.ldaptive.SearchResult@878591910::entries=[[dn=(correctDN)[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1737167252::baseDn=ou=Users,ou=PSD,dc=Peninsula,dc=wednet,dc=edu, searchFilter=[org.ldaptive.SearchFilter@1615263833::filter=(sAMAccountName={user}), parameters={user=username}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, 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@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 21:00:45,551 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolved dn=(correctDN) for user=username>
[STDOUT] 2016-10-25 21:00:45,556 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate dn=(correctDN) with request=[org.ldaptive.auth.AuthenticationRequest@1916764681::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]>
[STDOUT] 2016-10-25 21:00:45,562 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@1515358531::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1916764681::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:00:45,569 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1468837640::binddn=(correctDN), 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@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 21:00:45,604 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@121187832::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@1468837640::binddn=(correctDN), 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@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 21:00:45,612 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1232053453::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f], result=true, resultCode=SUCCESS, message=null, controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@1515358531::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1916764681::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:00:45,647 DEBUG [org.ldaptive.auth.SearchEntryResolver] - <resolve criteria=[org.ldaptive.auth.AuthenticationCriteria@1515358531::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1916764681::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:00:45,651 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-1249778521::basedn=(correctDN), searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired], searchScope=OBJECT, timeLimit=0, 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@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 21:00:45,750 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1867647831::result=[org.ldaptive.SearchResult@-634618133::entries=[[dn=(correctDN)[[mail[user...@psd401.net]], [givenName[BRANDON]], [displayName[MARTIN, BRANDON]], [memberOf[]], [sAMAccountName[username]]], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1249778521::basedn=(correctDN), searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired], searchScope=OBJECT, timeLimit=0, 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@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 21:00:45,770 DEBUG [org.ldaptive.auth.SearchEntryResolver] - <resolved result=[org.ldaptive.SearchResult@-634618133::entries=[[dn=(correctDN)[[mail[user...@psd401.net]], [givenName[BRANDON]], [displayName[MARTIN, BRANDON]], [memberOf[]], [sn[MARTIN]], [employeeID[MARTIBRA000]], [sAMAccountName[username]]], responseControls=null, messageId=-1]], references=[]] for criteria=[org.ldaptive.auth.AuthenticationCriteria@1515358531::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@1916764681::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:00:45,772 INFO [org.ldaptive.auth.Authenticator] - <Authentication succeeded for dn: CN=Martin\, Brandon L,OU=TSD,OU=Staff,OU=Users,OU=PSD,DC=Peninsula,DC=wednet,DC=edu>
[STDOUT] 2016-10-25 21:00:45,775 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1232053453::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f], result=true, resultCode=SUCCESS, message=null, controls=null] for dn=(correctDN) with request=[org.ldaptive.auth.AuthenticationRequest@1916764681::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]>
[STDOUT] 2016-10-25 21:00:45,788 INFO [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated username>
[STDOUT] 2016-10-25 21:00:45,801 INFO [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated username with credentials [username].>
[STDOUT] 2016-10-25 21:00:45,824 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
[STDOUT] =============================================================
[STDOUT] WHO: username
[STDOUT] WHAT: Supplied credentials: [username]
[STDOUT] ACTION: AUTHENTICATION_SUCCESS
[STDOUT] APPLICATION: CAS
[STDOUT] WHEN: Tue Oct 25 21:00:45 UTC 2016
[STDOUT] CLIENT IP ADDRESS: 172.17.0.1
[STDOUT] SERVER IP ADDRESS: 172.17.0.3
[STDOUT] =============================================================
[STDOUT] 
[STDOUT] >
[STDOUT] 2016-10-25 21:00:45,938 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
[STDOUT] =============================================================
[STDOUT] WHO: audit:unknown
[STDOUT] ACTION: TICKET_GRANTING_TICKET_CREATED
[STDOUT] APPLICATION: CAS
[STDOUT] WHEN: Tue Oct 25 21:00:45 UTC 2016
[STDOUT] CLIENT IP ADDRESS: 172.17.0.1
[STDOUT] SERVER IP ADDRESS: 172.17.0.3
[STDOUT] =============================================================
[STDOUT] 
[STDOUT] >
[STDOUT] 2016-10-25 21:00:49,950 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Reloading registered services.>
[STDOUT] 2016-10-25 21:00:49,961 INFO [org.jasig.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JsonServiceRegistryDao.>
[STDOUT] 2016-10-25 21:01:09,189 INFO [org.jasig.cas.ticket.registry.TicketRegistryCleaner] - <Beginning ticket cleanup...>
[STDOUT] 2016-10-25 21:01:09,190 INFO [org.jasig.cas.ticket.registry.TicketRegistryCleaner] - <0 expired tickets found and removed.>
[STDOUT] 2016-10-25 21:01:27,996 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolve user=username>
[STDOUT] 2016-10-25 21:01:27,998 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <searching for DN using userFilter>
[STDOUT] 2016-10-25 21:01:28,000 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1737167252::baseDn=ou=Users,ou=PSD,dc=Peninsula,dc=wednet,dc=edu, searchFilter=[org.ldaptive.SearchFilter@1615263833::filter=(sAMAccountName={user}), parameters={user=username}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, 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@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 21:01:28,028 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@81511301::result=[org.ldaptive.SearchResult@878591910::entries=[[dn=(correctDN)[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1737167252::baseDn=ou=Users,ou=PSD,dc=Peninsula,dc=wednet,dc=edu, searchFilter=[org.ldaptive.SearchFilter@1615263833::filter=(sAMAccountName={user}), parameters={user=username}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, 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@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 21:01:28,034 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolved dn=(correctDN) for user=username>
[STDOUT] 2016-10-25 21:01:28,040 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate dn=(correctDN) with request=[org.ldaptive.auth.AuthenticationRequest@14960582::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]>
[STDOUT] 2016-10-25 21:01:28,052 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@1172752830::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@14960582::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:01:28,053 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@787751976::binddn=(correctDN), 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@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 21:01:28,411 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1206179199::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f], result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903CF, comment: AcceptSecurityContext error, data 773, v2580], controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@1172752830::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@14960582::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:01:28,419 INFO [org.ldaptive.auth.Authenticator] - <Authentication failed for dn: CN=Martin\, Brandon L,OU=TSD,OU=Staff,OU=Users,OU=PSD,DC=Peninsula,DC=wednet,DC=edu>
[STDOUT] 2016-10-25 21:01:28,420 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1206179199::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f], result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903CF, comment: AcceptSecurityContext error, data 773, v2580], controls=null] for dn=(correctDN) with request=[org.ldaptive.auth.AuthenticationRequest@14960582::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]>
[STDOUT] 2016-10-25 21:01:28,424 INFO [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler failed authenticating username>
[STDOUT] 2016-10-25 21:01:28,428 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
[STDOUT] =============================================================
[STDOUT] WHO: username
[STDOUT] WHAT: Supplied credentials: [username]
[STDOUT] ACTION: AUTHENTICATION_FAILED
[STDOUT] APPLICATION: CAS
[STDOUT] WHEN: Tue Oct 25 21:01:28 UTC 2016
[STDOUT] CLIENT IP ADDRESS: 172.17.0.1
[STDOUT] SERVER IP ADDRESS: 172.17.0.3
[STDOUT] =============================================================
[STDOUT] 
[STDOUT] >
[STDOUT] 2016-10-25 21:01:42,338 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolve user=username>
[STDOUT] 2016-10-25 21:01:42,339 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <searching for DN using userFilter>
[STDOUT] 2016-10-25 21:01:42,341 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1737167252::baseDn=ou=Users,ou=PSD,dc=Peninsula,dc=wednet,dc=edu, searchFilter=[org.ldaptive.SearchFilter@1615263833::filter=(sAMAccountName={user}), parameters={user=username}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, 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@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 21:01:42,383 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1842253550::result=[org.ldaptive.SearchResult@878591910::entries=[[dn=(correctDN)[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1737167252::baseDn=ou=Users,ou=PSD,dc=Peninsula,dc=wednet,dc=edu, searchFilter=[org.ldaptive.SearchFilter@1615263833::filter=(sAMAccountName={user}), parameters={user=username}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=0, 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@300836639::config=[org.ldaptive.ConnectionConfig@542467430::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@240055488::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@404787971::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1662417126::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@64d53f0d, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@57df09a7]>
[STDOUT] 2016-10-25 21:01:42,384 DEBUG [org.ldaptive.auth.PooledSearchDnResolver] - <resolved dn=(correctDN) for user=username>
[STDOUT] 2016-10-25 21:01:42,385 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate dn=(correctDN) with request=[org.ldaptive.auth.AuthenticationRequest@131937946::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]>
[STDOUT] 2016-10-25 21:01:42,386 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@118379843::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@131937946::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:01:42,388 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1652278718::binddn=(correctDN), 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@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f]>
[STDOUT] 2016-10-25 21:01:42,555 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@2077990625::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f], result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903CF, comment: AcceptSecurityContext error, data 773, v2580], controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@118379843::dn=(correctDN), authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@131937946::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]]>
[STDOUT] 2016-10-25 21:01:42,556 INFO [org.ldaptive.auth.Authenticator] - <Authentication failed for dn: CN=Martin\, Brandon L,OU=TSD,OU=Staff,OU=Users,OU=PSD,DC=Peninsula,DC=wednet,DC=edu>
[STDOUT] 2016-10-25 21:01:42,557 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@2077990625::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@919561079::config=[org.ldaptive.ConnectionConfig@571943680::ldapUrl=ldap://xxx.xx.xx.xx, connectTimeout=3000, responseTimeout=-1, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@13642752::bindDn=admin...@peninsula.wednet.edu, bindSaslConfig=null, bindControls=null]], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@737128815::metadata=[ldapUrl=ldap://xxx.xx.xx.xx, count=1], environment={com.sun.jndi.ldap.connect.timeout=3000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@859450866::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.DefaultConnectionStrategy@1344f7fe, controlProcessor=org.ldaptive.provider.ControlProcessor@5ffdd510, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@3151277f], result=false, resultCode=INVALID_CREDENTIALS, message=javax.naming.AuthenticationException: [LDAP: error code 49 - 80090308: LdapErr: DSID-0C0903CF, comment: AcceptSecurityContext error, data 773, v2580], controls=null] for dn=(correctDN) with request=[org.ldaptive.auth.AuthenticationRequest@131937946::user=username, retAttrs=[telephoneNumber, mail, sAMAccountName, displayName, givenName, employeeId, memberOf, sn, passwordExpired]]>
[STDOUT] 2016-10-25 21:01:42,558 INFO [org.jasig.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler failed authenticating username>
[STDOUT] 2016-10-25 21:01:42,560 INFO [org.jasig.inspektr.audit.support.Slf4jLoggingAuditTrailManager] - <Audit trail record BEGIN
[STDOUT] =============================================================
[STDOUT] WHO: username
[STDOUT] WHAT: Supplied credentials: [username]
[STDOUT] ACTION: AUTHENTICATION_FAILED
[STDOUT] APPLICATION: CAS
[STDOUT] WHEN: Tue Oct 25 21:01:42 UTC 2016
[STDOUT] CLIENT IP ADDRESS: 172.17.0.1
[STDOUT] SERVER IP ADDRESS: 172.17.0.3
[STDOUT] =============================================================
[STDOUT] 
[STDOUT] >


I realize the error about 'metricsController' is a non issue.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/3f6e0d92-04a0-49ab-81aa-4c9207375722%40apereo.org.

Brandon Martin

unread,
Oct 25, 2016, 5:19:25 PM10/25/16
to CAS Community
It seems the logs were stripped. Here's a file instead:

I see that it says it can't find my log4j2.xml file, I have it in my overlay but it must be in the wrong place. Currently I'm adding it to /etc/cas

On Tuesday, October 25, 2016 at 2:13:10 PM UTC-7, Brandon Martin wrote:
Okay here we go:

--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/c5369bf5-dafc-437b-b949-9676ae402314%40apereo.org.
CAS-ldaptive-Logs.txt

Misagh Moayyed

unread,
Oct 25, 2016, 5:25:40 PM10/25/16
to CAS Community
You should set org.jasig.cas to DEBUG and that will get you more info.

Also, I’d have to defer to Daniel, but I believe in order for AD account states to be recognized, you need to switch to the ad-authenticator which should activate the right component that processes and reports back the account state back to CAS in a way that can be intercepted by the login process. 

-- 
Misagh
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/etPan.580fcdc7.41e93861.cbd6%40unicon.net.

Brandon Martin

unread,
Oct 25, 2016, 5:32:29 PM10/25/16
to CAS Community, mmoa...@unicon.net
Thank you for the feedback, I'm looking at the documentation here: https://apereo.github.io/cas/4.2.x/installation/LDAP-Authentication.html#configuration-1
It states bind-search-authenticator, I will try the standard ad-authenticator.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/7b131ff3-85aa-4811-9f5c-136ea3ceb5c7%40apereo.org.

Brandon Martin

unread,
Oct 25, 2016, 6:21:44 PM10/25/16
to CAS Community, mmoa...@unicon.net
This worked! Thank you!
I had tried the ad-authenticator while trying to setup AD binding, but now that I can authenticate to AD I hadn't tried this.

Thank you for your time! I'm not the best at CAS, but I am subscribed to this group and will contribute to the best of my abilities.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/5517f757-cd73-4b5d-8407-79d4b31883b7%40apereo.org.
Reply all
Reply to author
Forward
0 new messages