CAS Management App 5.0.0.RC2-SNAPSHOT
233 views
Skip to first unread message
Jeffrey Ramsay
Sep 18, 2016, 7:51:13 PM9/18/16
to CAS Community
I'm receiving this message "You are not authorized to access this resource. Contact your CAS administrator for more info." while trying to access the CAS management interface. I have tried using the "casuser" account along with my LDAP credentials but both accounts have failed. I tried adding my LDAP userid to the user-details.properties file but that too has been unsuccessful.
Has anyone been able to authenticate using LDAP as user store and the user-default.properties file to limit admin access? I tried the "cas.mgmt" options but that too has not been successful.
-Jeff
Has anyone been able to authenticate using LDAP as user store and the user-default.properties file to limit admin access? I tried the "cas.mgmt" options but that too has not been successful.
-Jeff
Jeffrey Ramsay
Sep 20, 2016, 11:00:42 AM9/20/16
to CAS Community
Is it possible to access the CAS 5 management console using an account other than "casuser"? Is so, can the admin users be placed in a static file and have their primary authentication source be LDAP? In CAS 3.4.x we only had to add the matching userid to deployerConfigContext.xml -> userDetailService block.
-Jeff
-Jeff
Misagh Moayyed
Sep 20, 2016, 11:04:30 AM9/20/16
to CAS Community
Yes, and yes.
From: "Jeffrey Ramsay" <jeffrey...@gmail.com>
To: "CAS Community" <cas-...@apereo.org>
Sent: Tuesday, September 20, 2016 7:30:42 PM
Subject: [cas-user] Re: CAS Management App 5.0.0.RC2-SNAPSHOT
To: "CAS Community" <cas-...@apereo.org>
Sent: Tuesday, September 20, 2016 7:30:42 PM
Subject: [cas-user] Re: CAS Management App 5.0.0.RC2-SNAPSHOT
--
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 post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/00a20f52-eb8a-4dc3-a689-6f0ff15e44f5%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
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 post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/00a20f52-eb8a-4dc3-a689-6f0ff15e44f5%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
Jeffrey Ramsay
Sep 20, 2016, 11:41:36 AM9/20/16
to CAS Community, mmoa...@unicon.net
Ok, how do I accomplish this? I have tried adding my userid to user-details.properties but do not want to have my password in clear text. So, what's the recipe to make this work?
jramsay=notused,ROLE_ADMIN
-Jeff
Jeffrey Ramsay
Sep 20, 2016, 11:58:16 AM9/20/16
to CAS Community
Is the following entry correct for the user-details.properties file when authenticating against LDAP? This matches my cas userid.
jramsay=notused,ROLE_ADMIN
Here's a snippet of my log:
2016-09-20 11:31:07,014 TRACE [org.ldaptive.provider.jndi.JndiConnectionFactory] - <[[ldapUrl=ldap://adpods.binghamton.edu:389, count=0]] Attempting connection to ldap://adpods.binghamton.edu:389 for strategy org.ldaptive.DefaultConnectionStrategy@50a0091f>
2016-09-20 11:31:07,016 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1433613577::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:31:07,021 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1194735987::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@1433613577::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:31:07,021 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2>
2016-09-20 11:31:07,021 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <initialized available queue: [org.ldaptive.pool.Queue@1099991255::queueType=LIFO, queue=[org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@51b80a3, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@10a5df26]]>
2016-09-20 11:31:07,027 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <prune pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]>
2016-09-20 11:31:07,027 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <validate pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]>
2016-09-20 11:31:07,027 INFO [org.ldaptive.pool.BlockingConnectionPool] - <pool initialized [org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]>
2016-09-20 11:31:07,050 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Initializing LDAP attribute configuration.>
2016-09-20 11:31:07,050 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Configured to retrieve principal id attribute cn>
2016-09-20 11:31:07,050 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Configured to retrieve principal attribute collection of [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]>
2016-09-20 11:31:07,051 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP authentication entry attributes are uid>
2016-09-20 11:31:07,484 DEBUG [org.apereo.cas.web.view.Cas30JsonResponseView] - <Initializing Cas30JsonResponseView>
2016-09-20 11:31:07,814 DEBUG [org.apereo.cas.web.flow.CasCaptchaWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:09,676 DEBUG [org.apereo.cas.web.flow.CasCaptchaWebflowConfigurer] - <Created evaluate action for expression validateCaptchaAction>
2016-09-20 11:31:09,727 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Using cipher [class com.sun.proxy.$Proxy283 to encrypt and decode the cookie>
2016-09-20 11:31:10,556 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:10,564 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Retrieved action state realSubmit>
2016-09-20 11:31:10,565 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Added transition mfa-gauth to the state realSubmit>
2016-09-20 11:31:10,635 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Registering flow definition [mfa-gauth]>
2016-09-20 11:31:10,636 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Added transition mfa-gauth to the state initialAuthenticationRequestValidationCheck>
2016-09-20 11:31:11,182 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:11,185 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state viewRedirectToUnauthorizedUrlView on flow id login, backed by view factory org.springframework.webflow.engine.support.ActionExecutingViewFactory@6f2f6fa7>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state redirectView on flow id login, backed by view factory org.springframework.webflow.engine.support.ActionExecutingViewFactory@19a43e90>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state viewServiceErrorView on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@5cb7db43>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state viewGenericLoginSuccess on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@65465656>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression genericSuccessViewAction>
2016-09-20 11:31:11,187 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state showWarningView on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@71005f0e>
2016-09-20 11:31:11,187 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression serviceWarningAction>
2016-09-20 11:31:11,189 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression terminateSessionAction>
2016-09-20 11:31:11,189 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created action state terminateSession>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Added action to the action state terminateSession list of actions: list[[EvaluateAction@607d144a expression = terminateSessionAction, resultExpression = [null]]]>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression serviceAuthorizationCheck>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created action state serviceAuthorizationCheck>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Added action to the action state serviceAuthorizationCheck list of actions: list[[EvaluateAction@5be95bf expression = serviceAuthorizationCheck, resultExpression = [null]]]>
Hibernate: select count(abstractre0_.id) as col_0_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:31:11,298 DEBUG [org.apereo.cas.services.ServiceRegistryInitializer] - <Service registry database will be auto-initialized from default JSON services>
Hibernate: select regexregis0_.id as id2_0_1_, regexregis0_.access_strategy as access_s3_0_1_, regexregis0_.attribute_release as attribut4_0_1_, regexregis0_.description as descript5_0_1_, regexregis0_.evaluation_order as evaluati6_0_1_, regexregis0_.logo as logo7_0_1_, regexregis0_.logout_type as logout_t8_0_1_, regexregis0_.logout_url as logout_u9_0_1_, regexregis0_.mfa_policy as mfa_pol10_0_1_, regexregis0_.name as name11_0_1_, regexregis0_.proxy_policy as proxy_p12_0_1_, regexregis0_.public_key as public_13_0_1_, regexregis0_.required_handlers as require14_0_1_, regexregis0_.serviceId as service15_0_1_, regexregis0_.theme as theme16_0_1_, regexregis0_.username_attr as usernam17_0_1_, properties1_.AbstractRegisteredService_id as Abstract1_2_3_, defaultreg2_.id as properti2_2_3_, properties1_.properties_KEY as properti3_3_, defaultreg2_.id as id1_1_0_, defaultreg2_.property_values as property2_1_0_ from RegexRegisteredService regexregis0_ left outer join RegisteredServiceImpl_Props properties1_ on regexregis0_.id=properties1_.AbstractRegisteredService_id left outer join RegexRegisteredServiceProperty defaultreg2_ on properties1_.properties_id=defaultreg2_.id where regexregis0_.id=? and regexregis0_.expression_type='regex'
2016-09-20 11:31:11,422 DEBUG [org.apereo.cas.services.ServiceRegistryInitializer] - <Initializing service registry database with the id=10000001,name=HTTPS and IMAPS,description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols.,serviceId=^(https|imaps)://.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=10000,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@631e7c0b[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@c170d4b[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@30cc1225[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@3fc78e0,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@27db9223[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> JSON service definition...>
Hibernate: call next value for hibernate_sequence
Hibernate: insert into RegexRegisteredService (access_strategy, attribute_release, description, evaluation_order, logo, logout_type, logout_url, mfa_policy, name, proxy_policy, public_key, required_handlers, serviceId, theme, username_attr, expression_type, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'regex', ?)
Hibernate: select regexregis0_.id as id2_0_1_, regexregis0_.access_strategy as access_s3_0_1_, regexregis0_.attribute_release as attribut4_0_1_, regexregis0_.description as descript5_0_1_, regexregis0_.evaluation_order as evaluati6_0_1_, regexregis0_.logo as logo7_0_1_, regexregis0_.logout_type as logout_t8_0_1_, regexregis0_.logout_url as logout_u9_0_1_, regexregis0_.mfa_policy as mfa_pol10_0_1_, regexregis0_.name as name11_0_1_, regexregis0_.proxy_policy as proxy_p12_0_1_, regexregis0_.public_key as public_13_0_1_, regexregis0_.required_handlers as require14_0_1_, regexregis0_.serviceId as service15_0_1_, regexregis0_.theme as theme16_0_1_, regexregis0_.username_attr as usernam17_0_1_, properties1_.AbstractRegisteredService_id as Abstract1_2_3_, defaultreg2_.id as properti2_2_3_, properties1_.properties_KEY as properti3_3_, defaultreg2_.id as id1_1_0_, defaultreg2_.property_values as property2_1_0_ from RegexRegisteredService regexregis0_ left outer join RegisteredServiceImpl_Props properties1_ on regexregis0_.id=properties1_.AbstractRegisteredService_id left outer join RegexRegisteredServiceProperty defaultreg2_ on properties1_.properties_id=defaultreg2_.id where regexregis0_.id=? and regexregis0_.expression_type='regex'
2016-09-20 11:31:11,551 DEBUG [org.apereo.cas.services.ServiceRegistryInitializer] - <Initializing service registry database with the id=10000002,name=Apereo,description=Apereo foundation sample service,serviceId=^https://www.apereo.org,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=apereo,evaluationOrder=1,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@7756f1c7[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@175a09b8[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@118c8bdc[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@6a3d5005,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@2aa5450d[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> JSON service definition...>
Hibernate: call next value for hibernate_sequence
Hibernate: insert into RegexRegisteredService (access_strategy, attribute_release, description, evaluation_order, logo, logout_type, logout_url, mfa_policy, name, proxy_policy, public_key, required_handlers, serviceId, theme, username_attr, expression_type, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'regex', ?)
Hibernate: select abstractre0_.id as id2_0_, abstractre0_.access_strategy as access_s3_0_, abstractre0_.attribute_release as attribut4_0_, abstractre0_.description as descript5_0_, abstractre0_.evaluation_order as evaluati6_0_, abstractre0_.logo as logo7_0_, abstractre0_.logout_type as logout_t8_0_, abstractre0_.logout_url as logout_u9_0_, abstractre0_.mfa_policy as mfa_pol10_0_, abstractre0_.name as name11_0_, abstractre0_.proxy_policy as proxy_p12_0_, abstractre0_.public_key as public_13_0_, abstractre0_.required_handlers as require14_0_, abstractre0_.serviceId as service15_0_, abstractre0_.theme as theme16_0_, abstractre0_.username_attr as usernam17_0_, abstractre0_.expression_type as expressi1_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:31:11,586 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from JpaServiceRegistryDaoImpl>
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
2016-09-20 11:31:11,644 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:31:11,645 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:31:11,645 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JpaServiceRegistryDaoImpl.>
2016-09-20 11:31:18,013 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Secret key for encryption is not defined. CAS will attempt to auto-generate the encryption key>
2016-09-20 11:31:18,021 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Generated encryption key lzuRp4PNFpjcOkUAtb9ntVnJtFFdAr1MLOuo2lbxWWM of size 256. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,021 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Secret key for signing is not defined. CAS will attempt to auto-generate the signing key>
2016-09-20 11:31:18,022 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Generated signing key wqDfsEv6yVWNNscZvE2VYYihqYR1Sc13UPE78Z9RP1UqtsB4XQuF4yNf4Cqquyzs_R-Z20HBUzvZmgoMyy5-yw of size 512. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,024 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Initialized cipher encryption sequence via [A128CBC-HS256]>
2016-09-20 11:31:18,431 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Secret key for signing is not defined. CAS will attempt to auto-generate the signing key>
2016-09-20 11:31:18,431 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Generated signing key PHY_BqniI8t6KBouVLJoTUYb39aOwyLXBYxj7hZjv8XzPXy0XcteceS3-7q4ZQ6QHpwXsT6Ium547tdRn_bdjA of size 512. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,431 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <No encryption key is defined. CAS will attempt to auto-generate keys>
2016-09-20 11:31:18,432 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Generated encryption key YKChpoDTyInJZuEV of size 16. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,512 WARN [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Runtime memory is used as the persistence storage for retrieving and managing tickets. Tickets that are issued during runtime will be LOST upon container restarts. This MAY impact SSO functionality.>
2016-09-20 11:31:18,725 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:18,726 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casAuthenticationBlockedView>
2016-09-20 11:31:18,726 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casBadWorkstationView>
2016-09-20 11:31:18,726 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casBadHoursView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casAccountLockedView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casAccountDisabledView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Flow login already contains a definition for state id casAccountDisabledView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Created end state state casPasswordUpdateSuccess on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@1e713946>
2016-09-20 11:31:18,728 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casMustChangePassView>
2016-09-20 11:31:18,728 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casExpiredPassView>
2016-09-20 11:31:18,953 INFO [org.apereo.cas.web.CasWebApplicationServletInitializer] - <Started CasWebApplicationServletInitializer in 29.796 seconds (JVM running for 62.178)>
20-Sep-2016 11:31:19.011 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /u01/app/badm/apps/dev/apache-tomcat-8.5.5-auth/webapps/cas5.war has finished in 34,863 ms
20-Sep-2016 11:31:19.015 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [http-nio-19006]
20-Sep-2016 11:31:19.021 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [ajp-nio-19009]
20-Sep-2016 11:31:19.022 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 60695 ms
Hibernate: select abstractre0_.id as id2_0_, abstractre0_.access_strategy as access_s3_0_, abstractre0_.attribute_release as attribut4_0_, abstractre0_.description as descript5_0_, abstractre0_.evaluation_order as evaluati6_0_, abstractre0_.logo as logo7_0_, abstractre0_.logout_type as logout_t8_0_, abstractre0_.logout_url as logout_u9_0_, abstractre0_.mfa_policy as mfa_pol10_0_, abstractre0_.name as name11_0_, abstractre0_.proxy_policy as proxy_p12_0_, abstractre0_.public_key as public_13_0_, abstractre0_.required_handlers as require14_0_, abstractre0_.serviceId as service15_0_, abstractre0_.theme as theme16_0_, abstractre0_.username_attr as usernam17_0_, abstractre0_.expression_type as expressi1_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:31:38,947 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from JpaServiceRegistryDaoImpl>
2016-09-20 11:31:38,992 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Attempting to acquire ticket cleanup lock.>
2016-09-20 11:31:38,992 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Acquired lock. Proceeding with cleanup.>
2016-09-20 11:31:38,993 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Beginning ticket cleanup...>
2016-09-20 11:31:38,996 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets found.>
2016-09-20 11:31:38,996 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-20 11:31:38,996 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Releasing ticket cleanup lock.>
2016-09-20 11:31:38,996 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
2016-09-20 11:31:39,030 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:31:39,031 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:31:39,031 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JpaServiceRegistryDaoImpl.>
2016-09-20 11:32:04,099 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from InMemoryServiceRegistryDaoImpl>
2016-09-20 11:32:04,100 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:32:04,100 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:32:04,101 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from InMemoryServiceRegistryDaoImpl.>
2016-09-20 11:32:16,298 INFO [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Setting path for cookies for warn cookie generator to: /cas5/ >
2016-09-20 11:32:16,299 DEBUG [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Setting path for cookies for TGC cookie generator to: /cas5/ >
2016-09-20 11:32:16,355 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:16,357 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:16,358 DEBUG [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Placing service in context scope: [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:16,387 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^https://www.apereo.org is a valid regex.>
2016-09-20 11:32:16,387 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^(https|imaps)://.* is a valid regex.>
2016-09-20 11:32:16,388 DEBUG [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Placing registered service [^(https|imaps)://.*] with id [1] in context scope>
2016-09-20 11:32:16,391 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:16,392 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:16,402 DEBUG [org.apereo.cas.web.flow.resolver.impl.RankedAuthenticationProviderWebflowEventResolver] - <Resolved single event [success] via [org.apereo.cas.web.flow.resolver.impl.RankedAuthenticationProviderWebflowEventResolver] for this context>
2016-09-20 11:32:16,406 DEBUG [org.apereo.cas.web.flow.InitializeLoginAction] - <Initialized login sequence>
2016-09-20 11:32:16,739 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:16,739 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:17,400 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages_en] - neither plain properties nor XML>
2016-09-20 11:32:17,401 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages] - neither plain properties nor XML>
2016-09-20 11:32:17,402 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:messages_en] - neither plain properties nor XML>
2016-09-20 11:32:17,403 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <Loading properties [messages.properties] with encoding 'UTF-8'>
2016-09-20 11:32:39,005 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Attempting to acquire ticket cleanup lock.>
2016-09-20 11:32:39,005 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Acquired lock. Proceeding with cleanup.>
2016-09-20 11:32:39,005 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Beginning ticket cleanup...>
2016-09-20 11:32:39,006 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets found.>
2016-09-20 11:32:39,006 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-20 11:32:39,006 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Releasing ticket cleanup lock.>
2016-09-20 11:32:39,007 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
Hibernate: select abstractre0_.id as id2_0_, abstractre0_.access_strategy as access_s3_0_, abstractre0_.attribute_release as attribut4_0_, abstractre0_.description as descript5_0_, abstractre0_.evaluation_order as evaluati6_0_, abstractre0_.logo as logo7_0_, abstractre0_.logout_type as logout_t8_0_, abstractre0_.logout_url as logout_u9_0_, abstractre0_.mfa_policy as mfa_pol10_0_, abstractre0_.name as name11_0_, abstractre0_.proxy_policy as proxy_p12_0_, abstractre0_.public_key as public_13_0_, abstractre0_.required_handlers as require14_0_, abstractre0_.serviceId as service15_0_, abstractre0_.theme as theme16_0_, abstractre0_.username_attr as usernam17_0_, abstractre0_.expression_type as expressi1_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:32:39,032 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from JpaServiceRegistryDaoImpl>
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
2016-09-20 11:32:39,139 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:32:39,140 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:32:39,140 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JpaServiceRegistryDaoImpl.>
2016-09-20 11:32:39,226 DEBUG [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Successfully decoded value. Result in Base64-encoding is [fXhgzLV57CDOTPZwMLxkvZZgxyKsO0i3qt7wDqqhlest6YycHjmh6HytrlkfXwKNi8HeQ0A56O5OaPSJQ0MEdYhWUgQMUpH+uNEFzp+JW16DFW5uK8IoCm+GdyJ/vauU0vQLlEWy8wYO0IE+1EBOnwC68hDfgyWiAiuAGSwvF8NwAwEQ9uGmGPkdANdyRxIzguupkxOvSqAeJilq26t7rv9g+Z9U0O9iM9bCVSzjTRt1hNHzlCVq73DY5uvbKYnhf8VGIbQGCw398LlHgPIrFfncykj8X4j76yqzzPZ3xHpvXestRu7L51BSkEeN7TLoKnvpDHF4+sirDMkNEIHddciyL39ZUDNzKPq6+qn8hnRs5Ku87PwnHq9DUOLVskl4+ltvPf2c9tZBNdX+xkiqHs9u8xsFxcxeQ0DfNHfB/CBCkB8PAR07K/v61rCOw6OFAQ2F5hoyLD5c4BPxYIk4kcP/gQwYy+8VkXrjA8f/bWyWGzQGicv6syh3hkjDYTXlaRi7xiJWQSjNe8NgtDTdPUAzGDAcDrDrfnMMv77YrKNn4/crR2kB2fCLUNsosFOKBpVoEojqT3ee2h2UCt+BCZWTsoEQpuPEET0r5oOvBOguOgSJF9gVBbwq98pTj1bR7f1Y9M5tTaFeuuEEy3a+ddUGiWrHJiUrNn+1Lfy7hIJXcuUgmfjBPvSE+lpzuLuwqBoXbdA3oXpr7ZHLWc9j9TuuE9yUpCIGXrEHGGzrGnkOSFPoeCcsjfiIj12nkTieWrjECCvv3XWIynMq2XMPOqOCdrxp/m/fOAei+IWlUNK/7TWUiuwodp6Em+o/H3XFZoyd48ItDH1aL6jzl4m6C4/NQQV1sr7sH0GFuSt4JFWr8trfN74t5R1lf/JOKRNi792BU1yMvN0wUwAAlNCYVDDC38vYnoNEh61NXGcbP/1dM+ssC9dzxfo3HmaCzzWgaf7W+Z9rEzMXK26VquROHhnMzfhIc7qiyoVrF2xi5zCXuG/ajGmZVbIb/W+Xx5rAbHBWaLcOCpfjGcE5uu28DNT5A7nGGCAB+DMyshkqtHP+wIBp1fdEwIwRIDq7EyfnXIjZs1wyAW1a/hhwMqs6wJtw88LKAStNwrcK3D4VmLPrDqzc4eNH3WYr97HY3kksFkvyr5ybHo3mkF0+puJWJC53CaIr9XlWej7b7tBUuwhpSZ/9Jt0bAuN13B9pmt+uZnNqmL01DDOYxX4k3+f6KYPKwfJb0pHHPWKimq+5lu3fcMKiDmWQXib3ok6xE2p+gDfv2roYkKMoWI2pwa68/LRxAQmpRZwFVaUOCndlCbZr5Sf37oRYZTB1AbysrgX5SwrtHjPxKoOzS4WW3KVIQHPqqQ71R+KlaKhJOS+NZpyL/DJQM38i395/qYXA3SjyODfvPGY1Y8aBs360Fet8RZqUXqVUs+FcG8uSjr3/b1S12Bm810ZUSkiBuMRBD1CnoEEKNww0AWlPepnk9e0TunginpX+xGG/k9purxV142RtRPbQp/3gpTvVpjL2LEfIpPqaQrMSExAMiH5HONbraX53mOtJVSFAvCZoAKSNuwFXJtWDqifGHpPFt4Yo6SQdVPoHslEisvyZqoS/lnZyzc8OQkAqtdLNkaxzzEASgtsb44NCLBinM2Efqb17bpKphYbS5uNqc/h18zhO6xdPPKoDtfV9xlQ7qcJ3oyUWpCiV2QMlFFL2n3DsoJUJp+rCfcpBwtWlKCCAywr5VG9cOiL/6gp6L9QRjpqG3B7b7jh1yWFi1cqSxbQz5XakAE0uAJnNM6TIl7lMXsSg8x1q/tt3kDKk4I0HPaa13VQoWOlR/4rlYrkfVI+LwEsPw9Uhj7gYZoFlfnK1Czbw6L0Ddz8rrE7MblrA1sQkZrmN/Pj2pM0CWu8inIpGulim/CFHDviNdo10+zBQIo4gusZ5Sljjc3J1fgLx5Jyq+816oXcLPZ231IDw0ZxUNaA/cwEDu6ZHVXETQ73WY0ADxF1G7ZXKmURatNeWw+/UqPnPsp9nWVDjb5qzgiT4uMP6C4zQzXsrShl0RI6VNNhFkoFx2AcJ2cXMqBz3CdyGtZ3yvndQqDO0t6IFdJu72djCRqT+nl4tU+ojk924ZodZgzi6IWQF9rdjqwVT692M0z+el5F1astRlkwL5PZdXKPSzZe9vk8j33GeEpoCROw2xZAGG+wmJmOe6dlSF6358eeMsXrNfJU2mHJ3lWG6ImyaQKunmGL3HZ2EALo5vjHeJEMr5GKa9/PSX2K9AsKCmhOQb6RO04ytUfKllq4OAbNB/qUwO7tieUQ49JcnpRbof+pP+v5IWWCZU0fX3ou8EmQHRW7+K4s4z77ILS++ppd2WwaqQeK2xuBzCitr31sCa2A8PhEa5MvlyuJFL0E2SCnMwNykqNzDAZ/WZCQOrH5/CzANFxpiSWGO9Qh1nDcDBgbPHtx3qS9HloPP1kNtFhJyjUCs6FUyO64t1TkZsm6BGi7tzzifo4oG4a6KNiygasK0upbqG5mZznVLwMkqBukchWovztpFgYEt1MapKeKy4Wuj/XmP6Mo4NcXZjxWHLfbUrTYNK+oeB9ctYz8qtCF30kJhVtMwNFxx67MgWY347xa88z88QPnH+qa4anFabrdK6Zf44oZu1jH7nqLDudFSorIUMnhvK6MLltV8MSoDRfh44iasSCcSYXyFznQQnmx9pghYBDJ3KtCNlUlb9vMsfgQkOCrNfdIpQWCOyvk1PPqZDOrMYZPPyaaMohq+NKsl4LaXYhvZSJVc1yXHDvuenMtXibrS+cujAHcSgVGVKcjfaTaejVQAu4RcsZzEMteuayZSGuJhuj3ly/gmRg2ye0ervFIHGLFVlRg8pZtGoGELtE0fqB2PF9iz2JwlG2p8JipsPnAuDxRygqlq3dc9XJCjKX+Eay+n/crnJ1kO2B9UlTpbyAsZ2lzEAOmtaWYKOoJndS0dC36SaMdzo1TF682htX0UINswn31GXrCurj/cWtxtWbn8u1HTcIAvSrkD5gw9a8iykDTNfVqA7kCB0H+DDlmPZZ+RXGZu5YqhmfReuke8vn0Ff3l0/LfsB13jtqxEM4ezgsakyALaVc/nvuHE51fG2bw45lfUyHKqslQA6Wj0f92Ae0vDR4PPpDaeoyzVH6/kJ+6IPYgMekHJDvY=]>
2016-09-20 11:32:39,259 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:39,260 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:39,261 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^https://www.apereo.org is a valid regex.>
2016-09-20 11:32:39,262 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^(https|imaps)://.* is a valid regex.>
2016-09-20 11:32:39,630 DEBUG [org.apereo.cas.web.flow.ValidateCaptchaAction] - <Sending 'POST' request to URL: https://www.google.com/recaptcha/api/siteverify>
2016-09-20 11:32:40,092 DEBUG [org.apereo.cas.web.flow.ValidateCaptchaAction] - <Response Code: 200>
2016-09-20 11:32:40,099 DEBUG [org.apereo.cas.web.flow.ValidateCaptchaAction] - <Google captcha response received: { "success": true, "challenge_ts": "2016-09-20T15:32:21Z", "hostname": "securedev.binghamton.edu"}>
2016-09-20 11:32:40,128 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Located client IP address as 128.226.31.55>
2016-09-20 11:32:40,129 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <User agent Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.116 Safari/537.36 is authorized to proceed>
2016-09-20 11:32:40,130 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Adaptive authentication policy has authorized client 128.226.31.55 to proceed.>
2016-09-20 11:32:40,131 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,131 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,132 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,133 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,219 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@6349456f, org.apereo.cas.adaptors.gauth.GoogleAuthenticatorAuthenticationHandler@4ae25385, org.apereo.cas.authentication.LdapAuthenticationHandler@3beac730]>
2016-09-20 11:32:40,234 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Attempting LDAP authentication for jramsay>
2016-09-20 11:32:40,244 DEBUG [org.ldaptive.auth.FormatDnResolver] - <Formatting DN for jramsay with cn=%s,cn=users,dc=pods,dc=bu,dc=int>
2016-09-20 11:32:40,244 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int with request=[org.ldaptive.auth.AuthenticationRequest@1279994763::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]>
2016-09-20 11:32:40,246 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,246 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2016-09-20 11:32:40,246 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2016-09-20 11:32:40,246 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2016-09-20 11:32:40,251 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@6be3348c>
2016-09-20 11:32:40,251 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2016-09-20 11:32:40,257 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,283 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2016-09-20 11:32:40,283 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2016-09-20 11:32:40,283 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2016-09-20 11:32:40,289 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@552083164::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2016-09-20 11:32:40,290 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@247994776::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,290 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602] = true>
2016-09-20 11:32:40,296 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@991966286::bindDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, 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@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,303 TRACE [org.ldaptive.provider.ControlProcessor] - <processing request controls: [[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]>
2016-09-20 11:32:40,304 TRACE [org.ldaptive.provider.ControlProcessor] - <produced provider request controls: [javax.naming.ldap.BasicControl@73fc386b]>
2016-09-20 11:32:40,310 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1229254686::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@991966286::bindDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, 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@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,313 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1415174272::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602], result=true, resultCode=SUCCESS, message=null, controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,313 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <resolve criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,313 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2016-09-20 11:32:40,313 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2016-09-20 11:32:40,313 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2016-09-20 11:32:40,320 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2>
2016-09-20 11:32:40,320 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2016-09-20 11:32:40,320 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,330 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@1584489109::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2016-09-20 11:32:40,331 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1289500240::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63] = true>
2016-09-20 11:32:40,331 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <searching for entry using userFilter>
2016-09-20 11:32:40,331 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-1246623327::baseDn=cn=users,dc=pods,dc=bu,dc=int, searchFilter=[org.ldaptive.SearchFilter@1127927486::filter=sAMAccountName={user}, parameters={context=null, dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, user=jramsay}], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,355 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int: null:null:{displayname=displayName: Jeffrey Ramsay, cn=cn: jramsay}>
2016-09-20 11:32:40,355 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn 'CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int'>
2016-09-20 11:32:40,356 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn 'CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int'>
2016-09-20 11:32:40,365 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@955366083::searchEntry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1]]>
2016-09-20 11:32:40,366 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1832977026::result=[org.ldaptive.SearchResult@963850531::entries=[[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1246623327::baseDn=cn=users,dc=pods,dc=bu,dc=int, searchFilter=[org.ldaptive.SearchFilter@1127927486::filter=sAMAccountName={user}, parameters={context=null, dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, user=jramsay}], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2>
2016-09-20 11:32:40,366 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <resolved result=[org.ldaptive.SearchResult@963850531::entries=[[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1]], references=[]] for criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.auth.Authenticator] - <resolved entry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1] with resolver=[org.ldaptive.auth.PooledSearchEntryResolver@1073928140::factory=[org.ldaptive.pool.PooledConnectionFactory@1430238298::pool=[org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]], baseDn=cn=users,dc=pods,dc=bu,dc=int, userFilter=sAMAccountName={user}, userFilterParameters=null, allowMultipleEntries=false, subtreeSearch=true, derefAliases=null, referralHandler=null, searchEntryHandlers=null]>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@6be3348c>
2016-09-20 11:32:40,367 INFO [org.ldaptive.auth.Authenticator] - <Authentication succeeded for dn: cn=jramsay,cn=users,dc=pods,dc=bu,dc=int>
2016-09-20 11:32:40,371 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1415174272::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602], result=true, resultCode=SUCCESS, message=null, controls=null] for dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int with request=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]>
2016-09-20 11:32:40,371 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response: [org.ldaptive.auth.AuthenticationResponse@1613577116::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, ldapEntry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2016-09-20 11:32:40,372 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Applying password policy to [org.ldaptive.auth.AuthenticationResponse@1613577116::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, ldapEntry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2016-09-20 11:32:40,373 DEBUG [org.apereo.cas.authentication.support.DefaultAccountStateHandler] - <Account state not defined. Returning empty list of messages.>
2016-09-20 11:32:40,375 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response returned as result. Creating the final LDAP principal>
2016-09-20 11:32:40,376 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Creating LDAP principal for jramsay based on CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int>
2016-09-20 11:32:40,377 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Retrieved principal id attribute jramsay>
2016-09-20 11:32:40,378 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [displayName[Jeffrey Ramsay]]>
2016-09-20 11:32:40,387 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [cn[jramsay]]>
2016-09-20 11:32:40,389 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Created LDAP principal for id jramsay and 3 attributes>
2016-09-20 11:32:40,393 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated jramsay>
2016-09-20 11:32:40,395 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <No resolver configured for LdapAuthenticationHandler. Falling back to handler principal jramsay>
2016-09-20 11:32:40,396 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is jramsay>
2016-09-20 11:32:40,431 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2016-09-20 11:32:40,433 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated jramsay with credentials [jramsay].>
2016-09-20 11:32:40,457 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute map for jramsay: {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:40,463 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Authentication org.apereo.cas.authentication.AbstractAuthenticationManager.authenticate(AuthenticationTransaction))]>
2016-09-20 11:32:40,478 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@4c619b23]>
2016-09-20 11:32:40,480 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Locating service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient in service registry to determine authentication policy>
2016-09-20 11:32:40,488 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via AdaptiveMultifactorAuthenticationWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,488 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,489 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,490 DEBUG [org.apereo.cas.web.flow.resolver.impl.AdaptiveMultifactorAuthenticationWebflowEventResolver] - <Adaptive authentication is not configured to require multifactor authentication>
2016-09-20 11:32:40,491 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for AdaptiveMultifactorAuthenticationWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,492 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RequestParameterAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,493 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,494 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,494 DEBUG [org.apereo.cas.web.flow.resolver.impl.RequestParameterAuthenticationPolicyWebflowEventResolver] - <No value could be found for request parameter authn_method>
2016-09-20 11:32:40,495 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RequestParameterAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,496 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,497 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,499 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,500 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Authentication policy is absent or does not contain any multifactor authentication providers>
2016-09-20 11:32:40,501 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,502 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via PrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,502 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,503 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,512 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Locating principal attribute value for attribute(s): [memberOf, eduPersonPrimaryAffiliation]>
2016-09-20 11:32:40,513 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Attribute value for memberOf to determine event is not configured for jramsay>
2016-09-20 11:32:40,514 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Attribute value for eduPersonPrimaryAffiliation to determine event is not configured for jramsay>
2016-09-20 11:32:40,515 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <No set of events based the principal attribute(s) [memberOf, eduPersonPrimaryAffiliation] could be matched>
2016-09-20 11:32:40,515 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for PrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,516 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServiceAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,517 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,519 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,519 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Authentication policy does not contain any multifactor authentication providers>
2016-09-20 11:32:40,520 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServiceAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,522 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Finalizing authentication transactions and issuing ticket-granting ticket>
2016-09-20 11:32:40,523 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-20 11:32:40,526 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [jramsay] for inclusion in result>
2016-09-20 11:32:40,527 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{commonName=jramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int, displayName=Jeffrey Ramsay}] for inclusion in this result for principal [jramsay]>
2016-09-20 11:32:40,530 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2016-09-20 11:32:40,531 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2016-09-20 11:32:40,532 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-20 11:32:40,536 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [jramsay] as the primary principal>
2016-09-20 11:32:40,537 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [jramsay]>
2016-09-20 11:32:40,538 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2016-09-20 11:32:40,539 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-20T11:32:40.539-04:00[US/Eastern]]>
2016-09-20 11:32:40,539 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@783196e3 and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,579 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jramsay>
2016-09-20 11:32:40,581 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}]>
2016-09-20 11:32:40,582 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [3] cached attributes for principal [jramsay] that are {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:40,583 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int} for jramsay>
2016-09-20 11:32:40,585 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for jramsay>
2016-09-20 11:32:40,591 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for jramsay>
2016-09-20 11:32:40,592 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2016-09-20 11:32:40,593 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2016-09-20 11:32:40,594 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2016-09-20 11:32:40,596 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2016-09-20 11:32:40,597 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2016-09-20 11:32:40,598 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2016-09-20 11:32:40,600 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2016-09-20 11:32:40,601 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {}>
2016-09-20 11:32:40,602 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2016-09-20 11:32:40,642 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus] to registry.>
2016-09-20 11:32:40,644 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasTicketGrantingTicketCreatedEvent@600690a[ticketGrantingTicket=TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus]>
2016-09-20 11:32:40,646 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(TicketGrantingTicket org.apereo.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket(AuthenticationResult))]>
2016-09-20 11:32:40,648 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resolved single event [success] via [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] for this context>
2016-09-20 11:32:40,649 DEBUG [org.apereo.cas.web.flow.SendTicketGrantingTicketAction] - <Setting TGC for current session.>
2016-09-20 11:32:40,650 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-1-AOmRKGsUb6jO0LdJB3lynKEZA...@128.226.31.55@Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.116 Safari/537.36]>
2016-09-20 11:32:40,652 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Encrypting via [A128CBC-HS256]>
2016-09-20 11:32:40,672 DEBUG [org.apereo.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Added cookie with name [TGC] and value [eyJhbGciOiJIUzUxMiJ9.WlhsS2FHSkhZMmxQYVVwcllWaEphVXhEU214aWJVMXBUMmxLUWsxVVNUUlJNRXBFVEZWb1ZFMXFWVEpKYmpBdUxsUmxZM2xrZUdSVE16VnRNa1ZFWDNWSlNITjJTSGN1Tlc5UE5GSlhZV2w0UzFGaFJrMDFUV3N3VVRWV1UxQnFOVU5KZW0xMFVFOXdiR3hSVUhjNU5tcEpRMGRQTVdoYVEwZGhNSGh3VTBGc1IwdFlaMnBqWTJsS1YwdDFWMjF2WlY5d1VVcHlZVGhHVVVwbWJESnFSa1F0UmpBMVVXWkRUMVZyU1ZBNVUyTllWelJTUjJkVlduUTVXRmRCVjJKTWEyWlFXa0pSTkdKT1ZXUnhWV3hsUW1kdk1VTnNSa0psUkZaSlpURlRaV1pEVm10dGFWaHZNbTg0UW1kdE16UnJSRUpOYUhGWVZFeDNkVlJQZUVGQ2FVcEhMVEJFVnpCbE9FcFVOMDlsZVUxb1JHSmtiVXA2ZFVwdU9XSnVWRmszUm1kTExVOW1NbWhRWjNjM1JqRTBlRVJHVkdSbFZ6ZGphUzEyVTFOMGNVWjZWMmxyZW01NmJpNVJPRVU1TUdFMlgxRTROWEpTVm5FMFlVTTFWbXBu.5x2MegTiyntSCjABoow9sVanqfZ39bn1Diye5_1isjsLsxb7mksVAMaNSoTLdTrVHVqInaih4SAZBPs9RyGkpg]>
2016-09-20 11:32:40,690 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-20 11:32:40,693 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [jramsay] for inclusion in result>
2016-09-20 11:32:40,693 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{commonName=jramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int, displayName=Jeffrey Ramsay}] for inclusion in this result for principal [jramsay]>
2016-09-20 11:32:40,694 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2016-09-20 11:32:40,695 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2016-09-20 11:32:40,695 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-20 11:32:40,696 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [jramsay] as the primary principal>
2016-09-20 11:32:40,697 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [jramsay]>
2016-09-20 11:32:40,697 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2016-09-20 11:32:40,698 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-20T11:32:40.698-04:00[US/Eastern]]>
2016-09-20 11:32:40,699 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@2f3df523 and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,704 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jramsay>
2016-09-20 11:32:40,705 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}]>
2016-09-20 11:32:40,706 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [3] cached attributes for principal [jramsay] that are {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:40,707 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int} for jramsay>
2016-09-20 11:32:40,708 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for jramsay>
2016-09-20 11:32:40,708 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for jramsay>
2016-09-20 11:32:40,709 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2016-09-20 11:32:40,710 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2016-09-20 11:32:40,713 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2016-09-20 11:32:40,714 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2016-09-20 11:32:40,715 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2016-09-20 11:32:40,716 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2016-09-20 11:32:40,719 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2016-09-20 11:32:40,719 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {}>
2016-09-20 11:32:40,720 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2016-09-20 11:32:40,721 DEBUG [org.apereo.cas.services.RegisteredServiceAccessStrategyUtils] - <Current authentication via ticket TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus allows service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient to participate in the existing SSO session>
2016-09-20 11:32:40,724 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Looking up service ticket id generator for [org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2016-09-20 11:32:40,732 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus] to registry.>
2016-09-20 11:32:40,733 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [ST-1-gllwwWzqBYPDHOtacVpk-venus] to registry.>
2016-09-20 11:32:40,734 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-1-gllwwWzqBYPDHOtacVpk-venus] for service [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient] and principal [jramsay]>
2016-09-20 11:32:40,735 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketGrantedEvent@6a359e00[ticketGrantingTicket=TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus,serviceTicket=ST-1-gllwwWzqBYPDHOtacVpk-venus]>
2016-09-20 11:32:40,737 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(ServiceTicket org.apereo.cas.CentralAuthenticationServiceImpl.grantServiceTicket(String,Service,AuthenticationResult))]>
2016-09-20 11:32:40,896 DEBUG [org.jasig.cas.client.session.HashMapBackedSessionMappingStorage] - <Attempting to remove Session=[09114431950B416756DA914C1DC667FE]>
2016-09-20 11:32:40,896 DEBUG [org.jasig.cas.client.session.HashMapBackedSessionMappingStorage] - <No mapping for session found. Ignoring.>
2016-09-20 11:32:40,897 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Placing URL parameters in map.>
2016-09-20 11:32:40,897 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Calling template URL attribute map.>
2016-09-20 11:32:40,897 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Loading custom parameters from configuration.>
2016-09-20 11:32:40,898 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Constructing validation url: https://securedev.binghamton.edu/cas5/p3/serviceValidate?ticket=ST-1-gllwwWzqBYPDHOtacVpk-venus&service=https%3A%2F%2Fsecuredev.binghamton.edu%2Fcas5-management%2Fcallback%3Fclient_name%3DCasClient>
2016-09-20 11:32:40,898 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Retrieving response from server.>
2016-09-20 11:32:41,016 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:41,016 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:41,022 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Located registered service definition id=1,name=HTTPS and IMAPS,description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols.,serviceId=^(https|imaps)://.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=10000,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@5ed39bc[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@63771e06[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@77223bdc[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@3bf95899,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@3cd3468f[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> from https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient to handle validation request>
2016-09-20 11:32:41,023 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Attribute policy [org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@5ed39bc[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@63771e06[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]]] is associated with service [id=1,name=HTTPS and IMAPS,description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols.,serviceId=^(https|imaps)://.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=10000,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@5ed39bc[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@63771e06[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@77223bdc[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@3bf95899,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@3cd3468f[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null>]>
2016-09-20 11:32:41,023 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jramsay>
2016-09-20 11:32:41,024 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}]>
2016-09-20 11:32:41,028 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [3] cached attributes for principal [jramsay] that are {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:41,029 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int} for jramsay>
2016-09-20 11:32:41,029 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for jramsay>
2016-09-20 11:32:41,030 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for jramsay>
2016-09-20 11:32:41,030 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2016-09-20 11:32:41,031 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2016-09-20 11:32:41,031 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2016-09-20 11:32:41,032 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2016-09-20 11:32:41,032 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2016-09-20 11:32:41,033 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2016-09-20 11:32:41,033 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2016-09-20 11:32:41,034 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {}>
2016-09-20 11:32:41,034 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider] - <Returning the default principal id [jramsay] for username.>
2016-09-20 11:32:41,049 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketValidatedEvent@7a2c2cd1[assertion=org.apereo.cas.authentication.DefaultAuthentication@783196e3:https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient,serviceTicket=ST-1-gllwwWzqBYPDHOtacVpk-venus]>
2016-09-20 11:32:41,051 DEBUG [org.apereo.cas.ticket.support.MultiTimeUseOrTimeoutExpirationPolicy] - <Ticket usage count 1 is greater than or equal to 1>
2016-09-20 11:32:41,051 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket [ST-1-gllwwWzqBYPDHOtacVpk-venus] from the registry.>
2016-09-20 11:32:41,052 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Assertion org.apereo.cas.CentralAuthenticationServiceImpl.validateServiceTicket(String,Service))]>
2016-09-20 11:32:41,071 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <Locating the primary authentication associated with this service request https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:41,093 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <No particular authentication context is required for this request>
2016-09-20 11:32:41,093 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <No service credentials specified, and/or the proxy handler [org.apereo.cas.ticket.proxy.support.Cas20ProxyHandler@36aa8aa5] cannot handle credentials>
2016-09-20 11:32:41,094 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <Successfully validated service ticket ST-1-gllwwWzqBYPDHOtacVpk-venus for service [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:41,097 DEBUG [org.apereo.cas.web.view.Cas30ResponseView] - <Preparing the output model to render view...>
2016-09-20 11:32:41,107 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <Starting to encode attributes for release to service [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:41,108 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[credential] is not available as a cached model attribute to encrypt...>
2016-09-20 11:32:41,108 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[proxyGrantingTicket] is not available as a cached model attribute to encrypt...>
2016-09-20 11:32:41,109 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[5] Encoded attributes are available for release to [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:41,113 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[false]]>
2016-09-20 11:32:41,114 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[true]]>
2016-09-20 11:32:41,115 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[2016-09-20T11:32:40.539-04:00[US/Eastern]]]>
2016-09-20 11:32:41,115 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting attribute [LdapAuthenticationHandler]>
2016-09-20 11:32:41,116 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[LdapAuthenticationHandler]]>
2016-09-20 11:32:41,164 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Server response: <cas:serviceResponse xmlns:cas="http://www.yale.edu/tp/cas"><cas:authenticationSuccess><cas:user>jramsay</cas:user>
<cas:attributes><cas:longTermAuthenticationRequestTokenUsed>false</cas:longTermAuthenticationRequestTokenUsed>
<cas:isFromNewLogin>true</cas:isFromNewLogin>
<cas:authenticationDate>2016-09-20T11:32:40.539-04:00[US/Eastern]</cas:authenticationDate>
<cas:authenticationMethod>LdapAuthenticationHandler</cas:authenticationMethod>
<cas:successfulAuthenticationHandlers>LdapAuthenticationHandler</cas:successfulAuthenticationHandlers>
</cas:attributes>
</cas:authenticationSuccess>
</cas:serviceResponse>
>
-Jeff
jramsay=notused,ROLE_ADMIN
Here's a snippet of my log:
2016-09-20 11:31:07,014 TRACE [org.ldaptive.provider.jndi.JndiConnectionFactory] - <[[ldapUrl=ldap://adpods.binghamton.edu:389, count=0]] Attempting connection to ldap://adpods.binghamton.edu:389 for strategy org.ldaptive.DefaultConnectionStrategy@50a0091f>
2016-09-20 11:31:07,016 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@1433613577::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:31:07,021 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1194735987::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@1433613577::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, saslConfig=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:31:07,021 INFO [org.ldaptive.pool.BlockingConnectionPool] - <added available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2>
2016-09-20 11:31:07,021 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <initialized available queue: [org.ldaptive.pool.Queue@1099991255::queueType=LIFO, queue=[org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@51b80a3, org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@10a5df26]]>
2016-09-20 11:31:07,027 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <prune pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]>
2016-09-20 11:31:07,027 DEBUG [org.ldaptive.pool.BlockingConnectionPool] - <validate pool task scheduled for [org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]>
2016-09-20 11:31:07,027 INFO [org.ldaptive.pool.BlockingConnectionPool] - <pool initialized [org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]>
2016-09-20 11:31:07,050 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Initializing LDAP attribute configuration.>
2016-09-20 11:31:07,050 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Configured to retrieve principal id attribute cn>
2016-09-20 11:31:07,050 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Configured to retrieve principal attribute collection of [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]>
2016-09-20 11:31:07,051 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP authentication entry attributes are uid>
2016-09-20 11:31:07,484 DEBUG [org.apereo.cas.web.view.Cas30JsonResponseView] - <Initializing Cas30JsonResponseView>
2016-09-20 11:31:07,814 DEBUG [org.apereo.cas.web.flow.CasCaptchaWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:09,676 DEBUG [org.apereo.cas.web.flow.CasCaptchaWebflowConfigurer] - <Created evaluate action for expression validateCaptchaAction>
2016-09-20 11:31:09,727 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Using cipher [class com.sun.proxy.$Proxy283 to encrypt and decode the cookie>
2016-09-20 11:31:10,556 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:10,564 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Retrieved action state realSubmit>
2016-09-20 11:31:10,565 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Added transition mfa-gauth to the state realSubmit>
2016-09-20 11:31:10,635 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Registering flow definition [mfa-gauth]>
2016-09-20 11:31:10,636 DEBUG [org.apereo.cas.adaptors.gauth.web.flow.GoogleAuthenticatorMultifactorWebflowConfigurer] - <Added transition mfa-gauth to the state initialAuthenticationRequestValidationCheck>
2016-09-20 11:31:11,182 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:11,185 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state viewRedirectToUnauthorizedUrlView on flow id login, backed by view factory org.springframework.webflow.engine.support.ActionExecutingViewFactory@6f2f6fa7>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state redirectView on flow id login, backed by view factory org.springframework.webflow.engine.support.ActionExecutingViewFactory@19a43e90>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state viewServiceErrorView on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@5cb7db43>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state viewGenericLoginSuccess on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@65465656>
2016-09-20 11:31:11,186 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression genericSuccessViewAction>
2016-09-20 11:31:11,187 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created end state state showWarningView on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@71005f0e>
2016-09-20 11:31:11,187 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression serviceWarningAction>
2016-09-20 11:31:11,189 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression terminateSessionAction>
2016-09-20 11:31:11,189 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created action state terminateSession>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Added action to the action state terminateSession list of actions: list[[EvaluateAction@607d144a expression = terminateSessionAction, resultExpression = [null]]]>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created evaluate action for expression serviceAuthorizationCheck>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Created action state serviceAuthorizationCheck>
2016-09-20 11:31:11,190 DEBUG [org.apereo.cas.web.flow.DefaultWebflowConfigurer] - <Added action to the action state serviceAuthorizationCheck list of actions: list[[EvaluateAction@5be95bf expression = serviceAuthorizationCheck, resultExpression = [null]]]>
Hibernate: select count(abstractre0_.id) as col_0_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:31:11,298 DEBUG [org.apereo.cas.services.ServiceRegistryInitializer] - <Service registry database will be auto-initialized from default JSON services>
Hibernate: select regexregis0_.id as id2_0_1_, regexregis0_.access_strategy as access_s3_0_1_, regexregis0_.attribute_release as attribut4_0_1_, regexregis0_.description as descript5_0_1_, regexregis0_.evaluation_order as evaluati6_0_1_, regexregis0_.logo as logo7_0_1_, regexregis0_.logout_type as logout_t8_0_1_, regexregis0_.logout_url as logout_u9_0_1_, regexregis0_.mfa_policy as mfa_pol10_0_1_, regexregis0_.name as name11_0_1_, regexregis0_.proxy_policy as proxy_p12_0_1_, regexregis0_.public_key as public_13_0_1_, regexregis0_.required_handlers as require14_0_1_, regexregis0_.serviceId as service15_0_1_, regexregis0_.theme as theme16_0_1_, regexregis0_.username_attr as usernam17_0_1_, properties1_.AbstractRegisteredService_id as Abstract1_2_3_, defaultreg2_.id as properti2_2_3_, properties1_.properties_KEY as properti3_3_, defaultreg2_.id as id1_1_0_, defaultreg2_.property_values as property2_1_0_ from RegexRegisteredService regexregis0_ left outer join RegisteredServiceImpl_Props properties1_ on regexregis0_.id=properties1_.AbstractRegisteredService_id left outer join RegexRegisteredServiceProperty defaultreg2_ on properties1_.properties_id=defaultreg2_.id where regexregis0_.id=? and regexregis0_.expression_type='regex'
2016-09-20 11:31:11,422 DEBUG [org.apereo.cas.services.ServiceRegistryInitializer] - <Initializing service registry database with the id=10000001,name=HTTPS and IMAPS,description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols.,serviceId=^(https|imaps)://.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=10000,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@631e7c0b[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@c170d4b[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@30cc1225[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@3fc78e0,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@27db9223[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> JSON service definition...>
Hibernate: call next value for hibernate_sequence
Hibernate: insert into RegexRegisteredService (access_strategy, attribute_release, description, evaluation_order, logo, logout_type, logout_url, mfa_policy, name, proxy_policy, public_key, required_handlers, serviceId, theme, username_attr, expression_type, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'regex', ?)
Hibernate: select regexregis0_.id as id2_0_1_, regexregis0_.access_strategy as access_s3_0_1_, regexregis0_.attribute_release as attribut4_0_1_, regexregis0_.description as descript5_0_1_, regexregis0_.evaluation_order as evaluati6_0_1_, regexregis0_.logo as logo7_0_1_, regexregis0_.logout_type as logout_t8_0_1_, regexregis0_.logout_url as logout_u9_0_1_, regexregis0_.mfa_policy as mfa_pol10_0_1_, regexregis0_.name as name11_0_1_, regexregis0_.proxy_policy as proxy_p12_0_1_, regexregis0_.public_key as public_13_0_1_, regexregis0_.required_handlers as require14_0_1_, regexregis0_.serviceId as service15_0_1_, regexregis0_.theme as theme16_0_1_, regexregis0_.username_attr as usernam17_0_1_, properties1_.AbstractRegisteredService_id as Abstract1_2_3_, defaultreg2_.id as properti2_2_3_, properties1_.properties_KEY as properti3_3_, defaultreg2_.id as id1_1_0_, defaultreg2_.property_values as property2_1_0_ from RegexRegisteredService regexregis0_ left outer join RegisteredServiceImpl_Props properties1_ on regexregis0_.id=properties1_.AbstractRegisteredService_id left outer join RegexRegisteredServiceProperty defaultreg2_ on properties1_.properties_id=defaultreg2_.id where regexregis0_.id=? and regexregis0_.expression_type='regex'
2016-09-20 11:31:11,551 DEBUG [org.apereo.cas.services.ServiceRegistryInitializer] - <Initializing service registry database with the id=10000002,name=Apereo,description=Apereo foundation sample service,serviceId=^https://www.apereo.org,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=apereo,evaluationOrder=1,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@7756f1c7[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@175a09b8[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@118c8bdc[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@6a3d5005,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@2aa5450d[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> JSON service definition...>
Hibernate: call next value for hibernate_sequence
Hibernate: insert into RegexRegisteredService (access_strategy, attribute_release, description, evaluation_order, logo, logout_type, logout_url, mfa_policy, name, proxy_policy, public_key, required_handlers, serviceId, theme, username_attr, expression_type, id) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 'regex', ?)
Hibernate: select abstractre0_.id as id2_0_, abstractre0_.access_strategy as access_s3_0_, abstractre0_.attribute_release as attribut4_0_, abstractre0_.description as descript5_0_, abstractre0_.evaluation_order as evaluati6_0_, abstractre0_.logo as logo7_0_, abstractre0_.logout_type as logout_t8_0_, abstractre0_.logout_url as logout_u9_0_, abstractre0_.mfa_policy as mfa_pol10_0_, abstractre0_.name as name11_0_, abstractre0_.proxy_policy as proxy_p12_0_, abstractre0_.public_key as public_13_0_, abstractre0_.required_handlers as require14_0_, abstractre0_.serviceId as service15_0_, abstractre0_.theme as theme16_0_, abstractre0_.username_attr as usernam17_0_, abstractre0_.expression_type as expressi1_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:31:11,586 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from JpaServiceRegistryDaoImpl>
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
2016-09-20 11:31:11,644 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:31:11,645 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:31:11,645 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JpaServiceRegistryDaoImpl.>
2016-09-20 11:31:18,013 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Secret key for encryption is not defined. CAS will attempt to auto-generate the encryption key>
2016-09-20 11:31:18,021 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Generated encryption key lzuRp4PNFpjcOkUAtb9ntVnJtFFdAr1MLOuo2lbxWWM of size 256. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,021 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Secret key for signing is not defined. CAS will attempt to auto-generate the signing key>
2016-09-20 11:31:18,022 WARN [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Generated signing key wqDfsEv6yVWNNscZvE2VYYihqYR1Sc13UPE78Z9RP1UqtsB4XQuF4yNf4Cqquyzs_R-Z20HBUzvZmgoMyy5-yw of size 512. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,024 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Initialized cipher encryption sequence via [A128CBC-HS256]>
2016-09-20 11:31:18,431 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Secret key for signing is not defined. CAS will attempt to auto-generate the signing key>
2016-09-20 11:31:18,431 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Generated signing key PHY_BqniI8t6KBouVLJoTUYb39aOwyLXBYxj7hZjv8XzPXy0XcteceS3-7q4ZQ6QHpwXsT6Ium547tdRn_bdjA of size 512. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,431 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <No encryption key is defined. CAS will attempt to auto-generate keys>
2016-09-20 11:31:18,432 WARN [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Generated encryption key YKChpoDTyInJZuEV of size 16. The generated key MUST be added to CAS settings.>
2016-09-20 11:31:18,512 WARN [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Runtime memory is used as the persistence storage for retrieving and managing tickets. Tickets that are issued during runtime will be LOST upon container restarts. This MAY impact SSO functionality.>
2016-09-20 11:31:18,725 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Initializing CAS webflow configuration...>
2016-09-20 11:31:18,726 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casAuthenticationBlockedView>
2016-09-20 11:31:18,726 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casBadWorkstationView>
2016-09-20 11:31:18,726 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casBadHoursView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casAccountLockedView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casAccountDisabledView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Flow login already contains a definition for state id casAccountDisabledView>
2016-09-20 11:31:18,727 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Created end state state casPasswordUpdateSuccess on flow id login, backed by view factory org.springframework.webflow.mvc.servlet.ServletMvcViewFactory@1e713946>
2016-09-20 11:31:18,728 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casMustChangePassView>
2016-09-20 11:31:18,728 DEBUG [org.apereo.cas.web.flow.PasswordManagementWebflowConfigurer] - <Added view state casExpiredPassView>
2016-09-20 11:31:18,953 INFO [org.apereo.cas.web.CasWebApplicationServletInitializer] - <Started CasWebApplicationServletInitializer in 29.796 seconds (JVM running for 62.178)>
20-Sep-2016 11:31:19.011 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /u01/app/badm/apps/dev/apache-tomcat-8.5.5-auth/webapps/cas5.war has finished in 34,863 ms
20-Sep-2016 11:31:19.015 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [http-nio-19006]
20-Sep-2016 11:31:19.021 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [ajp-nio-19009]
20-Sep-2016 11:31:19.022 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 60695 ms
Hibernate: select abstractre0_.id as id2_0_, abstractre0_.access_strategy as access_s3_0_, abstractre0_.attribute_release as attribut4_0_, abstractre0_.description as descript5_0_, abstractre0_.evaluation_order as evaluati6_0_, abstractre0_.logo as logo7_0_, abstractre0_.logout_type as logout_t8_0_, abstractre0_.logout_url as logout_u9_0_, abstractre0_.mfa_policy as mfa_pol10_0_, abstractre0_.name as name11_0_, abstractre0_.proxy_policy as proxy_p12_0_, abstractre0_.public_key as public_13_0_, abstractre0_.required_handlers as require14_0_, abstractre0_.serviceId as service15_0_, abstractre0_.theme as theme16_0_, abstractre0_.username_attr as usernam17_0_, abstractre0_.expression_type as expressi1_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:31:38,947 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from JpaServiceRegistryDaoImpl>
2016-09-20 11:31:38,992 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Attempting to acquire ticket cleanup lock.>
2016-09-20 11:31:38,992 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Acquired lock. Proceeding with cleanup.>
2016-09-20 11:31:38,993 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Beginning ticket cleanup...>
2016-09-20 11:31:38,996 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets found.>
2016-09-20 11:31:38,996 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-20 11:31:38,996 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Releasing ticket cleanup lock.>
2016-09-20 11:31:38,996 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
2016-09-20 11:31:39,030 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:31:39,031 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:31:39,031 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JpaServiceRegistryDaoImpl.>
2016-09-20 11:32:04,099 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from InMemoryServiceRegistryDaoImpl>
2016-09-20 11:32:04,100 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:32:04,100 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:32:04,101 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from InMemoryServiceRegistryDaoImpl.>
2016-09-20 11:32:16,298 INFO [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Setting path for cookies for warn cookie generator to: /cas5/ >
2016-09-20 11:32:16,299 DEBUG [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Setting path for cookies for TGC cookie generator to: /cas5/ >
2016-09-20 11:32:16,355 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:16,357 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:16,358 DEBUG [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Placing service in context scope: [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:16,387 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^https://www.apereo.org is a valid regex.>
2016-09-20 11:32:16,387 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^(https|imaps)://.* is a valid regex.>
2016-09-20 11:32:16,388 DEBUG [org.apereo.cas.web.flow.InitialFlowSetupAction] - <Placing registered service [^(https|imaps)://.*] with id [1] in context scope>
2016-09-20 11:32:16,391 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:16,392 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:16,402 DEBUG [org.apereo.cas.web.flow.resolver.impl.RankedAuthenticationProviderWebflowEventResolver] - <Resolved single event [success] via [org.apereo.cas.web.flow.resolver.impl.RankedAuthenticationProviderWebflowEventResolver] for this context>
2016-09-20 11:32:16,406 DEBUG [org.apereo.cas.web.flow.InitializeLoginAction] - <Initialized login sequence>
2016-09-20 11:32:16,739 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:16,739 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:17,400 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages_en] - neither plain properties nor XML>
2016-09-20 11:32:17,401 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:custom_messages] - neither plain properties nor XML>
2016-09-20 11:32:17,402 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <No properties file found for [classpath:messages_en] - neither plain properties nor XML>
2016-09-20 11:32:17,403 DEBUG [org.apereo.cas.web.view.CasReloadableMessageBundle] - <Loading properties [messages.properties] with encoding 'UTF-8'>
2016-09-20 11:32:39,005 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Attempting to acquire ticket cleanup lock.>
2016-09-20 11:32:39,005 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Acquired lock. Proceeding with cleanup.>
2016-09-20 11:32:39,005 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Beginning ticket cleanup...>
2016-09-20 11:32:39,006 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets found.>
2016-09-20 11:32:39,006 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <0 expired tickets removed.>
2016-09-20 11:32:39,006 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Releasing ticket cleanup lock.>
2016-09-20 11:32:39,007 INFO [org.apereo.cas.ticket.registry.DefaultTicketRegistryCleaner] - <Finished ticket cleanup.>
Hibernate: select abstractre0_.id as id2_0_, abstractre0_.access_strategy as access_s3_0_, abstractre0_.attribute_release as attribut4_0_, abstractre0_.description as descript5_0_, abstractre0_.evaluation_order as evaluati6_0_, abstractre0_.logo as logo7_0_, abstractre0_.logout_type as logout_t8_0_, abstractre0_.logout_url as logout_u9_0_, abstractre0_.mfa_policy as mfa_pol10_0_, abstractre0_.name as name11_0_, abstractre0_.proxy_policy as proxy_p12_0_, abstractre0_.public_key as public_13_0_, abstractre0_.required_handlers as require14_0_, abstractre0_.serviceId as service15_0_, abstractre0_.theme as theme16_0_, abstractre0_.username_attr as usernam17_0_, abstractre0_.expression_type as expressi1_0_ from RegexRegisteredService abstractre0_
2016-09-20 11:32:39,032 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loading services from JpaServiceRegistryDaoImpl>
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
Hibernate: select properties0_.AbstractRegisteredService_id as Abstract1_2_0_, properties0_.properties_id as properti2_2_0_, properties0_.properties_KEY as properti3_0_, defaultreg1_.id as id1_1_1_, defaultreg1_.property_values as property2_1_1_ from RegisteredServiceImpl_Props properties0_ inner join RegexRegisteredServiceProperty defaultreg1_ on properties0_.properties_id=defaultreg1_.id where properties0_.AbstractRegisteredService_id=?
2016-09-20 11:32:39,139 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^(https|imaps)://.*>
2016-09-20 11:32:39,140 DEBUG [org.apereo.cas.services.DefaultServicesManagerImpl] - <Adding registered service ^https://www.apereo.org>
2016-09-20 11:32:39,140 INFO [org.apereo.cas.services.DefaultServicesManagerImpl] - <Loaded 2 services from JpaServiceRegistryDaoImpl.>
2016-09-20 11:32:39,226 DEBUG [org.apereo.cas.util.cipher.WebflowConversationStateCipherExecutor] - <Successfully decoded value. Result in Base64-encoding is [fXhgzLV57CDOTPZwMLxkvZZgxyKsO0i3qt7wDqqhlest6YycHjmh6HytrlkfXwKNi8HeQ0A56O5OaPSJQ0MEdYhWUgQMUpH+uNEFzp+JW16DFW5uK8IoCm+GdyJ/vauU0vQLlEWy8wYO0IE+1EBOnwC68hDfgyWiAiuAGSwvF8NwAwEQ9uGmGPkdANdyRxIzguupkxOvSqAeJilq26t7rv9g+Z9U0O9iM9bCVSzjTRt1hNHzlCVq73DY5uvbKYnhf8VGIbQGCw398LlHgPIrFfncykj8X4j76yqzzPZ3xHpvXestRu7L51BSkEeN7TLoKnvpDHF4+sirDMkNEIHddciyL39ZUDNzKPq6+qn8hnRs5Ku87PwnHq9DUOLVskl4+ltvPf2c9tZBNdX+xkiqHs9u8xsFxcxeQ0DfNHfB/CBCkB8PAR07K/v61rCOw6OFAQ2F5hoyLD5c4BPxYIk4kcP/gQwYy+8VkXrjA8f/bWyWGzQGicv6syh3hkjDYTXlaRi7xiJWQSjNe8NgtDTdPUAzGDAcDrDrfnMMv77YrKNn4/crR2kB2fCLUNsosFOKBpVoEojqT3ee2h2UCt+BCZWTsoEQpuPEET0r5oOvBOguOgSJF9gVBbwq98pTj1bR7f1Y9M5tTaFeuuEEy3a+ddUGiWrHJiUrNn+1Lfy7hIJXcuUgmfjBPvSE+lpzuLuwqBoXbdA3oXpr7ZHLWc9j9TuuE9yUpCIGXrEHGGzrGnkOSFPoeCcsjfiIj12nkTieWrjECCvv3XWIynMq2XMPOqOCdrxp/m/fOAei+IWlUNK/7TWUiuwodp6Em+o/H3XFZoyd48ItDH1aL6jzl4m6C4/NQQV1sr7sH0GFuSt4JFWr8trfN74t5R1lf/JOKRNi792BU1yMvN0wUwAAlNCYVDDC38vYnoNEh61NXGcbP/1dM+ssC9dzxfo3HmaCzzWgaf7W+Z9rEzMXK26VquROHhnMzfhIc7qiyoVrF2xi5zCXuG/ajGmZVbIb/W+Xx5rAbHBWaLcOCpfjGcE5uu28DNT5A7nGGCAB+DMyshkqtHP+wIBp1fdEwIwRIDq7EyfnXIjZs1wyAW1a/hhwMqs6wJtw88LKAStNwrcK3D4VmLPrDqzc4eNH3WYr97HY3kksFkvyr5ybHo3mkF0+puJWJC53CaIr9XlWej7b7tBUuwhpSZ/9Jt0bAuN13B9pmt+uZnNqmL01DDOYxX4k3+f6KYPKwfJb0pHHPWKimq+5lu3fcMKiDmWQXib3ok6xE2p+gDfv2roYkKMoWI2pwa68/LRxAQmpRZwFVaUOCndlCbZr5Sf37oRYZTB1AbysrgX5SwrtHjPxKoOzS4WW3KVIQHPqqQ71R+KlaKhJOS+NZpyL/DJQM38i395/qYXA3SjyODfvPGY1Y8aBs360Fet8RZqUXqVUs+FcG8uSjr3/b1S12Bm810ZUSkiBuMRBD1CnoEEKNww0AWlPepnk9e0TunginpX+xGG/k9purxV142RtRPbQp/3gpTvVpjL2LEfIpPqaQrMSExAMiH5HONbraX53mOtJVSFAvCZoAKSNuwFXJtWDqifGHpPFt4Yo6SQdVPoHslEisvyZqoS/lnZyzc8OQkAqtdLNkaxzzEASgtsb44NCLBinM2Efqb17bpKphYbS5uNqc/h18zhO6xdPPKoDtfV9xlQ7qcJ3oyUWpCiV2QMlFFL2n3DsoJUJp+rCfcpBwtWlKCCAywr5VG9cOiL/6gp6L9QRjpqG3B7b7jh1yWFi1cqSxbQz5XakAE0uAJnNM6TIl7lMXsSg8x1q/tt3kDKk4I0HPaa13VQoWOlR/4rlYrkfVI+LwEsPw9Uhj7gYZoFlfnK1Czbw6L0Ddz8rrE7MblrA1sQkZrmN/Pj2pM0CWu8inIpGulim/CFHDviNdo10+zBQIo4gusZ5Sljjc3J1fgLx5Jyq+816oXcLPZ231IDw0ZxUNaA/cwEDu6ZHVXETQ73WY0ADxF1G7ZXKmURatNeWw+/UqPnPsp9nWVDjb5qzgiT4uMP6C4zQzXsrShl0RI6VNNhFkoFx2AcJ2cXMqBz3CdyGtZ3yvndQqDO0t6IFdJu72djCRqT+nl4tU+ojk924ZodZgzi6IWQF9rdjqwVT692M0z+el5F1astRlkwL5PZdXKPSzZe9vk8j33GeEpoCROw2xZAGG+wmJmOe6dlSF6358eeMsXrNfJU2mHJ3lWG6ImyaQKunmGL3HZ2EALo5vjHeJEMr5GKa9/PSX2K9AsKCmhOQb6RO04ytUfKllq4OAbNB/qUwO7tieUQ49JcnpRbof+pP+v5IWWCZU0fX3ou8EmQHRW7+K4s4z77ILS++ppd2WwaqQeK2xuBzCitr31sCa2A8PhEa5MvlyuJFL0E2SCnMwNykqNzDAZ/WZCQOrH5/CzANFxpiSWGO9Qh1nDcDBgbPHtx3qS9HloPP1kNtFhJyjUCs6FUyO64t1TkZsm6BGi7tzzifo4oG4a6KNiygasK0upbqG5mZznVLwMkqBukchWovztpFgYEt1MapKeKy4Wuj/XmP6Mo4NcXZjxWHLfbUrTYNK+oeB9ctYz8qtCF30kJhVtMwNFxx67MgWY347xa88z88QPnH+qa4anFabrdK6Zf44oZu1jH7nqLDudFSorIUMnhvK6MLltV8MSoDRfh44iasSCcSYXyFznQQnmx9pghYBDJ3KtCNlUlb9vMsfgQkOCrNfdIpQWCOyvk1PPqZDOrMYZPPyaaMohq+NKsl4LaXYhvZSJVc1yXHDvuenMtXibrS+cujAHcSgVGVKcjfaTaejVQAu4RcsZzEMteuayZSGuJhuj3ly/gmRg2ye0ervFIHGLFVlRg8pZtGoGELtE0fqB2PF9iz2JwlG2p8JipsPnAuDxRygqlq3dc9XJCjKX+Eay+n/crnJ1kO2B9UlTpbyAsZ2lzEAOmtaWYKOoJndS0dC36SaMdzo1TF682htX0UINswn31GXrCurj/cWtxtWbn8u1HTcIAvSrkD5gw9a8iykDTNfVqA7kCB0H+DDlmPZZ+RXGZu5YqhmfReuke8vn0Ff3l0/LfsB13jtqxEM4ezgsakyALaVc/nvuHE51fG2bw45lfUyHKqslQA6Wj0f92Ae0vDR4PPpDaeoyzVH6/kJ+6IPYgMekHJDvY=]>
2016-09-20 11:32:39,259 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:39,260 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:39,261 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^https://www.apereo.org is a valid regex.>
2016-09-20 11:32:39,262 DEBUG [org.apereo.cas.util.RegexUtils] - <Pattern ^(https|imaps)://.* is a valid regex.>
2016-09-20 11:32:39,630 DEBUG [org.apereo.cas.web.flow.ValidateCaptchaAction] - <Sending 'POST' request to URL: https://www.google.com/recaptcha/api/siteverify>
2016-09-20 11:32:40,092 DEBUG [org.apereo.cas.web.flow.ValidateCaptchaAction] - <Response Code: 200>
2016-09-20 11:32:40,099 DEBUG [org.apereo.cas.web.flow.ValidateCaptchaAction] - <Google captcha response received: { "success": true, "challenge_ts": "2016-09-20T15:32:21Z", "hostname": "securedev.binghamton.edu"}>
2016-09-20 11:32:40,128 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Located client IP address as 128.226.31.55>
2016-09-20 11:32:40,129 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <User agent Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.116 Safari/537.36 is authorized to proceed>
2016-09-20 11:32:40,130 DEBUG [org.apereo.cas.authentication.adaptive.DefaultAdaptiveAuthenticationPolicy] - <Adaptive authentication policy has authorized client 128.226.31.55 to proceed.>
2016-09-20 11:32:40,131 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,131 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,132 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,133 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,219 DEBUG [org.apereo.cas.authentication.RegisteredServiceAuthenticationHandlerResolver] - <Authentication handlers used for this transaction are [org.apereo.cas.authentication.handler.support.HttpBasedServiceCredentialsAuthenticationHandler@6349456f, org.apereo.cas.adaptors.gauth.GoogleAuthenticatorAuthenticationHandler@4ae25385, org.apereo.cas.authentication.LdapAuthenticationHandler@3beac730]>
2016-09-20 11:32:40,234 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Attempting LDAP authentication for jramsay>
2016-09-20 11:32:40,244 DEBUG [org.ldaptive.auth.FormatDnResolver] - <Formatting DN for jramsay with cn=%s,cn=users,dc=pods,dc=bu,dc=int>
2016-09-20 11:32:40,244 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int with request=[org.ldaptive.auth.AuthenticationRequest@1279994763::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]>
2016-09-20 11:32:40,246 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,246 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2016-09-20 11:32:40,246 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2016-09-20 11:32:40,246 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2016-09-20 11:32:40,251 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@6be3348c>
2016-09-20 11:32:40,251 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2016-09-20 11:32:40,257 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,283 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2016-09-20 11:32:40,283 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2016-09-20 11:32:40,283 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2016-09-20 11:32:40,289 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@552083164::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2016-09-20 11:32:40,290 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@247994776::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,290 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602] = true>
2016-09-20 11:32:40,296 DEBUG [org.ldaptive.BindOperation] - <execute request=[org.ldaptive.BindRequest@991966286::bindDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, 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@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,303 TRACE [org.ldaptive.provider.ControlProcessor] - <processing request controls: [[org.ldaptive.control.PasswordPolicyControl@-350057371::criticality=false, timeBeforeExpiration=0, graceAuthNsRemaining=0, error=null]]>
2016-09-20 11:32:40,304 TRACE [org.ldaptive.provider.ControlProcessor] - <produced provider request controls: [javax.naming.ldap.BasicControl@73fc386b]>
2016-09-20 11:32:40,310 DEBUG [org.ldaptive.BindOperation] - <execute response=[org.ldaptive.Response@1229254686::result=null, resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.BindRequest@991966286::bindDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, 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@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602]>
2016-09-20 11:32:40,313 DEBUG [org.ldaptive.auth.PooledBindAuthenticationHandler] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1415174272::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602], result=true, resultCode=SUCCESS, message=null, controls=null] for criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,313 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <resolve criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,313 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check out 0>
2016-09-20 11:32:40,313 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieve available connection from pool of size 3>
2016-09-20 11:32:40,313 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for retrieve available 0>
2016-09-20 11:32:40,320 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <retrieved available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2>
2016-09-20 11:32:40,320 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no activator configured>
2016-09-20 11:32:40,320 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,330 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: : null:null:No attributes>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn ''>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn ''>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@1584489109::searchEntry=[dn=[], responseControls=null, messageId=-1]]>
2016-09-20 11:32:40,331 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1289500240::result=[org.ldaptive.SearchResult@-1951941189::entries=[[dn=[], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,331 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <validation for [org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63] = true>
2016-09-20 11:32:40,331 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <searching for entry using userFilter>
2016-09-20 11:32:40,331 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@-1246623327::baseDn=cn=users,dc=pods,dc=bu,dc=int, searchFilter=[org.ldaptive.SearchFilter@1127927486::filter=sAMAccountName={user}, parameters={context=null, dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, user=jramsay}], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,355 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <reading search result: CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int: null:null:{displayname=displayName: Jeffrey Ramsay, cn=cn: jramsay}>
2016-09-20 11:32:40,355 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatting relative dn 'CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int'>
2016-09-20 11:32:40,356 TRACE [org.ldaptive.provider.jndi.JndiConnection] - <formatted dn 'CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int'>
2016-09-20 11:32:40,365 TRACE [org.ldaptive.SearchOperation] - <Received search item=[org.ldaptive.provider.SearchItem@955366083::searchEntry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1]]>
2016-09-20 11:32:40,366 DEBUG [org.ldaptive.SearchOperation] - <execute response=[org.ldaptive.Response@1832977026::result=[org.ldaptive.SearchResult@963850531::entries=[[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1]], references=[]], resultCode=SUCCESS, message=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1] for request=[org.ldaptive.SearchRequest@-1246623327::baseDn=cn=users,dc=pods,dc=bu,dc=int, searchFilter=[org.ldaptive.SearchFilter@1127927486::filter=sAMAccountName={user}, parameters={context=null, dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, user=jramsay}], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1890505163::config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1705614669::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@436912864::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@200818f5, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@b219e63]>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@70afafd2>
2016-09-20 11:32:40,366 DEBUG [org.ldaptive.auth.PooledSearchEntryResolver] - <resolved result=[org.ldaptive.SearchResult@963850531::entries=[[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1]], references=[]] for criteria=[org.ldaptive.auth.AuthenticationCriteria@634520062::dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, authenticationRequest=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]]>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.auth.Authenticator] - <resolved entry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1] with resolver=[org.ldaptive.auth.PooledSearchEntryResolver@1073928140::factory=[org.ldaptive.pool.PooledConnectionFactory@1430238298::pool=[org.ldaptive.pool.BlockingConnectionPool@1575463995::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@594686538::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT10M], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@727203702::searchRequest=[org.ldaptive.SearchRequest@1227724184::baseDn=, searchFilter=[org.ldaptive.SearchFilter@1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=PT0S, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1185638788::prunePeriod=PT2H46M40S, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@119678952::provider=org.ldaptive.provider.jndi.JndiProvider@25de877, config=[org.ldaptive.ConnectionConfig@1651677049::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1293761849::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@592758222::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50a0091f]], initialized=true, availableCount=3, activeCount=0]], baseDn=cn=users,dc=pods,dc=bu,dc=int, userFilter=sAMAccountName={user}, userFilterParameters=null, allowMultipleEntries=false, subtreeSearch=true, derefAliases=null, referralHandler=null, searchEntryHandlers=null]>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <no passivator configured>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <waiting on pool lock for check in 0>
2016-09-20 11:32:40,366 TRACE [org.ldaptive.pool.BlockingConnectionPool] - <returned active connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy@6be3348c>
2016-09-20 11:32:40,367 INFO [org.ldaptive.auth.Authenticator] - <Authentication succeeded for dn: cn=jramsay,cn=users,dc=pods,dc=bu,dc=int>
2016-09-20 11:32:40,371 DEBUG [org.ldaptive.auth.Authenticator] - <authenticate response=[org.ldaptive.auth.AuthenticationHandlerResponse@1415174272::connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1809995397::config=[org.ldaptive.ConnectionConfig@1399047156::ldapUrl=ldap://adpods.binghamton.edu:389, connectTimeout=PT1H23M20S, responseTimeout=null, sslConfig=[org.ldaptive.ssl.SslConfig@1228852620::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@1051382678::bindDn=cn=ampodchg,cn=users,dc=pods,dc=bu,dc=int, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@53686c19], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@160333301::metadata=[ldapUrl=ldap://adpods.binghamton.edu:389, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@452863880::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@6d57a4b4, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], classLoader=null, sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection@54974602], result=true, resultCode=SUCCESS, message=null, controls=null] for dn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int with request=[org.ldaptive.auth.AuthenticationRequest@904555673::user=[org.ldaptive.auth.User@727760324::identifier=jramsay, context=null], returnAttributes=[uid, affiliation, displayName, cn,sn,givenName,displayName, cn, [uid, affiliation, displayName, cn,sn,givenName,displayName, cn]]]>
2016-09-20 11:32:40,371 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response: [org.ldaptive.auth.AuthenticationResponse@1613577116::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, ldapEntry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2016-09-20 11:32:40,372 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Applying password policy to [org.ldaptive.auth.AuthenticationResponse@1613577116::authenticationResultCode=AUTHENTICATION_HANDLER_SUCCESS, resolvedDn=cn=jramsay,cn=users,dc=pods,dc=bu,dc=int, ldapEntry=[dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int[[displayName[Jeffrey Ramsay]], [cn[jramsay]]], responseControls=null, messageId=-1], accountState=null, result=true, resultCode=SUCCESS, message=null, controls=null]>
2016-09-20 11:32:40,373 DEBUG [org.apereo.cas.authentication.support.DefaultAccountStateHandler] - <Account state not defined. Returning empty list of messages.>
2016-09-20 11:32:40,375 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <LDAP response returned as result. Creating the final LDAP principal>
2016-09-20 11:32:40,376 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Creating LDAP principal for jramsay based on CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int>
2016-09-20 11:32:40,377 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Retrieved principal id attribute jramsay>
2016-09-20 11:32:40,378 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [displayName[Jeffrey Ramsay]]>
2016-09-20 11:32:40,387 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Found principal attribute: [cn[jramsay]]>
2016-09-20 11:32:40,389 DEBUG [org.apereo.cas.authentication.LdapAuthenticationHandler] - <Created LDAP principal for id jramsay and 3 attributes>
2016-09-20 11:32:40,393 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <LdapAuthenticationHandler successfully authenticated jramsay>
2016-09-20 11:32:40,395 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <No resolver configured for LdapAuthenticationHandler. Falling back to handler principal jramsay>
2016-09-20 11:32:40,396 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Final principal resolved for this authentication event is jramsay>
2016-09-20 11:32:40,431 DEBUG [org.apereo.cas.authentication.AnyAuthenticationPolicy] - <Authentication policy is satisfied having found at least one authentication transactions>
2016-09-20 11:32:40,433 INFO [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authenticated jramsay with credentials [jramsay].>
2016-09-20 11:32:40,457 DEBUG [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Attribute map for jramsay: {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:40,463 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Authentication org.apereo.cas.authentication.AbstractAuthenticationManager.authenticate(AuthenticationTransaction))]>
2016-09-20 11:32:40,478 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationTransactionManager] - <Successful authentication; Collecting authentication result [org.apereo.cas.authentication.DefaultAuthentication@4c619b23]>
2016-09-20 11:32:40,480 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Locating service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient in service registry to determine authentication policy>
2016-09-20 11:32:40,488 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via AdaptiveMultifactorAuthenticationWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,488 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,489 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,490 DEBUG [org.apereo.cas.web.flow.resolver.impl.AdaptiveMultifactorAuthenticationWebflowEventResolver] - <Adaptive authentication is not configured to require multifactor authentication>
2016-09-20 11:32:40,491 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for AdaptiveMultifactorAuthenticationWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,492 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RequestParameterAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,493 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,494 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,494 DEBUG [org.apereo.cas.web.flow.resolver.impl.RequestParameterAuthenticationPolicyWebflowEventResolver] - <No value could be found for request parameter authn_method>
2016-09-20 11:32:40,495 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RequestParameterAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,496 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,497 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,499 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,500 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Authentication policy is absent or does not contain any multifactor authentication providers>
2016-09-20 11:32:40,501 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServicePrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,502 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via PrincipalAttributeAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,502 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,503 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,512 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Locating principal attribute value for attribute(s): [memberOf, eduPersonPrimaryAffiliation]>
2016-09-20 11:32:40,513 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Attribute value for memberOf to determine event is not configured for jramsay>
2016-09-20 11:32:40,514 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <Attribute value for eduPersonPrimaryAffiliation to determine event is not configured for jramsay>
2016-09-20 11:32:40,515 DEBUG [org.apereo.cas.web.flow.resolver.impl.PrincipalAttributeAuthenticationPolicyWebflowEventResolver] - <No set of events based the principal attribute(s) [memberOf, eduPersonPrimaryAffiliation] could be matched>
2016-09-20 11:32:40,515 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for PrincipalAttributeAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,516 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Evaluating authentication policy via RegisteredServiceAuthenticationPolicyWebflowEventResolver for registered service ^(https|imaps)://.* and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,517 DEBUG [org.apereo.cas.web.support.WebUtils] - <Evaluating request to determine if warning cookie should be generated>
2016-09-20 11:32:40,519 DEBUG [org.apereo.cas.web.WarningCookieRetrievingCookieGenerator] - <Removed cookie with name [CASPRIVACY]>
2016-09-20 11:32:40,519 DEBUG [org.apereo.cas.web.flow.resolver.impl.RegisteredServiceAuthenticationPolicyWebflowEventResolver] - <Authentication policy does not contain any multifactor authentication providers>
2016-09-20 11:32:40,520 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resulting event for RegisteredServiceAuthenticationPolicyWebflowEventResolver is blank/ignored>
2016-09-20 11:32:40,522 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Finalizing authentication transactions and issuing ticket-granting ticket>
2016-09-20 11:32:40,523 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-20 11:32:40,526 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [jramsay] for inclusion in result>
2016-09-20 11:32:40,527 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{commonName=jramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int, displayName=Jeffrey Ramsay}] for inclusion in this result for principal [jramsay]>
2016-09-20 11:32:40,530 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2016-09-20 11:32:40,531 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2016-09-20 11:32:40,532 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-20 11:32:40,536 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [jramsay] as the primary principal>
2016-09-20 11:32:40,537 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [jramsay]>
2016-09-20 11:32:40,538 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2016-09-20 11:32:40,539 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-20T11:32:40.539-04:00[US/Eastern]]>
2016-09-20 11:32:40,539 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@783196e3 and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,579 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jramsay>
2016-09-20 11:32:40,581 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}]>
2016-09-20 11:32:40,582 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [3] cached attributes for principal [jramsay] that are {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:40,583 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int} for jramsay>
2016-09-20 11:32:40,585 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for jramsay>
2016-09-20 11:32:40,591 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for jramsay>
2016-09-20 11:32:40,592 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2016-09-20 11:32:40,593 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2016-09-20 11:32:40,594 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2016-09-20 11:32:40,596 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2016-09-20 11:32:40,597 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2016-09-20 11:32:40,598 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2016-09-20 11:32:40,600 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2016-09-20 11:32:40,601 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {}>
2016-09-20 11:32:40,602 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2016-09-20 11:32:40,642 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus] to registry.>
2016-09-20 11:32:40,644 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasTicketGrantingTicketCreatedEvent@600690a[ticketGrantingTicket=TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus]>
2016-09-20 11:32:40,646 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(TicketGrantingTicket org.apereo.cas.CentralAuthenticationServiceImpl.createTicketGrantingTicket(AuthenticationResult))]>
2016-09-20 11:32:40,648 DEBUG [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] - <Resolved single event [success] via [org.apereo.cas.web.flow.resolver.impl.InitialAuthenticationAttemptWebflowEventResolver] for this context>
2016-09-20 11:32:40,649 DEBUG [org.apereo.cas.web.flow.SendTicketGrantingTicketAction] - <Setting TGC for current session.>
2016-09-20 11:32:40,650 DEBUG [org.apereo.cas.web.support.DefaultCasCookieValueManager] - <Encoding cookie value [TGT-1-AOmRKGsUb6jO0LdJB3lynKEZA...@128.226.31.55@Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/53.0.2785.116 Safari/537.36]>
2016-09-20 11:32:40,652 DEBUG [org.apereo.cas.util.cipher.TicketGrantingCookieCipherExecutor] - <Encrypting via [A128CBC-HS256]>
2016-09-20 11:32:40,672 DEBUG [org.apereo.cas.web.support.TGCCookieRetrievingCookieGenerator] - <Added cookie with name [TGC] and value [eyJhbGciOiJIUzUxMiJ9.WlhsS2FHSkhZMmxQYVVwcllWaEphVXhEU214aWJVMXBUMmxLUWsxVVNUUlJNRXBFVEZWb1ZFMXFWVEpKYmpBdUxsUmxZM2xrZUdSVE16VnRNa1ZFWDNWSlNITjJTSGN1Tlc5UE5GSlhZV2w0UzFGaFJrMDFUV3N3VVRWV1UxQnFOVU5KZW0xMFVFOXdiR3hSVUhjNU5tcEpRMGRQTVdoYVEwZGhNSGh3VTBGc1IwdFlaMnBqWTJsS1YwdDFWMjF2WlY5d1VVcHlZVGhHVVVwbWJESnFSa1F0UmpBMVVXWkRUMVZyU1ZBNVUyTllWelJTUjJkVlduUTVXRmRCVjJKTWEyWlFXa0pSTkdKT1ZXUnhWV3hsUW1kdk1VTnNSa0psUkZaSlpURlRaV1pEVm10dGFWaHZNbTg0UW1kdE16UnJSRUpOYUhGWVZFeDNkVlJQZUVGQ2FVcEhMVEJFVnpCbE9FcFVOMDlsZVUxb1JHSmtiVXA2ZFVwdU9XSnVWRmszUm1kTExVOW1NbWhRWjNjM1JqRTBlRVJHVkdSbFZ6ZGphUzEyVTFOMGNVWjZWMmxyZW01NmJpNVJPRVU1TUdFMlgxRTROWEpTVm5FMFlVTTFWbXBu.5x2MegTiyntSCjABoow9sVanqfZ39bn1Diye5_1isjsLsxb7mksVAMaNSoTLdTrVHVqInaih4SAZBPs9RyGkpg]>
2016-09-20 11:32:40,690 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collecting authentication history based on [1] authentication events>
2016-09-20 11:32:40,693 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Evaluating authentication principal [jramsay] for inclusion in result>
2016-09-20 11:32:40,693 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected principal attributes [{commonName=jramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int, displayName=Jeffrey Ramsay}] for inclusion in this result for principal [jramsay]>
2016-09-20 11:32:40,694 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [authenticationMethod] -> [LdapAuthenticationHandler]>
2016-09-20 11:32:40,695 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected single authentication attribute [successfulAuthenticationHandlers] -> [[LdapAuthenticationHandler]]>
2016-09-20 11:32:40,695 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Finalized authentication attributes [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}] for inclusion in this authentication result>
2016-09-20 11:32:40,696 DEBUG [org.apereo.cas.authentication.DefaultPrincipalElectionStrategy] - <Nominated [jramsay] as the primary principal>
2016-09-20 11:32:40,697 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Determined primary authentication principal to be [jramsay]>
2016-09-20 11:32:40,697 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Collected authentication attributes for this result are [{authenticationMethod=LdapAuthenticationHandler, successfulAuthenticationHandlers=[LdapAuthenticationHandler]}]>
2016-09-20 11:32:40,698 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Authentication result commenced at [2016-09-20T11:32:40.698-04:00[US/Eastern]]>
2016-09-20 11:32:40,699 DEBUG [org.apereo.cas.authentication.DefaultAuthenticationResultBuilder] - <Building an authentication result for authentication org.apereo.cas.authentication.DefaultAuthentication@2f3df523 and service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:40,704 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jramsay>
2016-09-20 11:32:40,705 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}]>
2016-09-20 11:32:40,706 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [3] cached attributes for principal [jramsay] that are {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:40,707 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int} for jramsay>
2016-09-20 11:32:40,708 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for jramsay>
2016-09-20 11:32:40,708 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for jramsay>
2016-09-20 11:32:40,709 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2016-09-20 11:32:40,710 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2016-09-20 11:32:40,713 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2016-09-20 11:32:40,714 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2016-09-20 11:32:40,715 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2016-09-20 11:32:40,716 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2016-09-20 11:32:40,719 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2016-09-20 11:32:40,719 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {}>
2016-09-20 11:32:40,720 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy] - <Skipping access strategy policy, since no attributes rules are defined>
2016-09-20 11:32:40,721 DEBUG [org.apereo.cas.services.RegisteredServiceAccessStrategyUtils] - <Current authentication via ticket TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus allows service https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient to participate in the existing SSO session>
2016-09-20 11:32:40,724 DEBUG [org.apereo.cas.ticket.DefaultServiceTicketFactory] - <Looking up service ticket id generator for [org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl]>
2016-09-20 11:32:40,732 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus] to registry.>
2016-09-20 11:32:40,733 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Added ticket [ST-1-gllwwWzqBYPDHOtacVpk-venus] to registry.>
2016-09-20 11:32:40,734 INFO [org.apereo.cas.CentralAuthenticationServiceImpl] - <Granted ticket [ST-1-gllwwWzqBYPDHOtacVpk-venus] for service [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient] and principal [jramsay]>
2016-09-20 11:32:40,735 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketGrantedEvent@6a359e00[ticketGrantingTicket=TGT-1-AOmRKGsUb6jO0LdJB3lynKEZAQehqaY9A2tyYOUvBMifQSL2Ge-venus,serviceTicket=ST-1-gllwwWzqBYPDHOtacVpk-venus]>
2016-09-20 11:32:40,737 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(ServiceTicket org.apereo.cas.CentralAuthenticationServiceImpl.grantServiceTicket(String,Service,AuthenticationResult))]>
2016-09-20 11:32:40,896 DEBUG [org.jasig.cas.client.session.HashMapBackedSessionMappingStorage] - <Attempting to remove Session=[09114431950B416756DA914C1DC667FE]>
2016-09-20 11:32:40,896 DEBUG [org.jasig.cas.client.session.HashMapBackedSessionMappingStorage] - <No mapping for session found. Ignoring.>
2016-09-20 11:32:40,897 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Placing URL parameters in map.>
2016-09-20 11:32:40,897 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Calling template URL attribute map.>
2016-09-20 11:32:40,897 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Loading custom parameters from configuration.>
2016-09-20 11:32:40,898 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Constructing validation url: https://securedev.binghamton.edu/cas5/p3/serviceValidate?ticket=ST-1-gllwwWzqBYPDHOtacVpk-venus&service=https%3A%2F%2Fsecuredev.binghamton.edu%2Fcas5-management%2Fcallback%3Fclient_name%3DCasClient>
2016-09-20 11:32:40,898 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Retrieving response from server.>
2016-09-20 11:32:41,016 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Created https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient based on org.apereo.cas.authentication.principal.WebApplicationServiceFactory@4a2a8296>
2016-09-20 11:32:41,016 DEBUG [org.apereo.cas.web.support.DefaultArgumentExtractor] - <Extractor generated service type org.apereo.cas.authentication.principal.SimpleWebApplicationServiceImpl for: https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:41,022 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Located registered service definition id=1,name=HTTPS and IMAPS,description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols.,serviceId=^(https|imaps)://.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=10000,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@5ed39bc[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@63771e06[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@77223bdc[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@3bf95899,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@3cd3468f[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null> from https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient to handle validation request>
2016-09-20 11:32:41,023 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Attribute policy [org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@5ed39bc[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@63771e06[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]]] is associated with service [id=1,name=HTTPS and IMAPS,description=This service definition authorizes all application urls that support HTTPS and IMAPS protocols.,serviceId=^(https|imaps)://.*,usernameAttributeProvider=org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider@d,theme=<null>,evaluationOrder=10000,logoutType=BACK_CHANNEL,attributeReleasePolicy=org.apereo.cas.services.ReturnAllowedAttributeReleasePolicy@5ed39bc[attributeFilter=<null>,principalAttributesRepository=org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository@63771e06[],authorizedToReleaseCredentialPassword=false,authorizedToReleaseProxyGrantingTicket=false,allowedAttributes=[]],accessStrategy=org.apereo.cas.services.DefaultRegisteredServiceAccessStrategy@77223bdc[enabled=true,ssoEnabled=true,requireAllAttributes=true,requiredAttributes={},unauthorizedRedirectUrl=<null>,caseInsensitive=false,rejectedAttributes={}],publicKey=<null>,proxyPolicy=org.apereo.cas.services.RefuseRegisteredServiceProxyPolicy@3bf95899,logo=<null>,logoutUrl=<null>,requiredHandlers=[],properties={},multifactorPolicy=org.apereo.cas.services.DefaultRegisteredServiceMultifactorPolicy@3cd3468f[multifactorAuthenticationProviders=[],failureMode=CLOSED,principalAttributeNameTrigger=<null>,principalAttributeValueToMatch=<null>],<null>]>
2016-09-20 11:32:41,023 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Locating principal attributes for jramsay>
2016-09-20 11:32:41,024 DEBUG [org.apereo.cas.authentication.principal.DefaultPrincipalAttributesRepository] - <DefaultPrincipalAttributesRepository will return the collection of attributes directly associated with the principal object which are [{commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}]>
2016-09-20 11:32:41,028 DEBUG [org.apereo.cas.authentication.principal.cache.AbstractPrincipalAttributesRepository] - <Found [3] cached attributes for principal [jramsay] that are {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int}>
2016-09-20 11:32:41,029 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Found principal attributes {commonName=jramsay, displayName=Jeffrey Ramsay, LdapAuthenticationHandler.dn=CN=jramsay,CN=Users,DC=pods,DC=bu,DC=int} for jramsay>
2016-09-20 11:32:41,029 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Calling attribute policy ReturnAllowedAttributeReleasePolicy to process attributes for jramsay>
2016-09-20 11:32:41,030 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attribute policy ReturnAllowedAttributeReleasePolicy allows release of {} for jramsay>
2016-09-20 11:32:41,030 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Checking default attribute policy attributes>
2016-09-20 11:32:41,031 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Located application context. Retrieving default attributes for release, if any>
2016-09-20 11:32:41,031 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes for release are: []>
2016-09-20 11:32:41,032 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Default attributes found to be released are {}>
2016-09-20 11:32:41,032 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Attempting to merge policy attributes and default attributes>
2016-09-20 11:32:41,033 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding default attributes first to the released set of attributes>
2016-09-20 11:32:41,033 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Adding policy attributes to the released set of attributes>
2016-09-20 11:32:41,034 DEBUG [org.apereo.cas.services.AbstractRegisteredServiceAttributeReleasePolicy] - <Final collection of attributes allowed are: {}>
2016-09-20 11:32:41,034 DEBUG [org.apereo.cas.services.DefaultRegisteredServiceUsernameProvider] - <Returning the default principal id [jramsay] for username.>
2016-09-20 11:32:41,049 DEBUG [org.apereo.cas.CentralAuthenticationServiceImpl] - <Publishing org.apereo.cas.support.events.CasServiceTicketValidatedEvent@7a2c2cd1[assertion=org.apereo.cas.authentication.DefaultAuthentication@783196e3:https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient,serviceTicket=ST-1-gllwwWzqBYPDHOtacVpk-venus]>
2016-09-20 11:32:41,051 DEBUG [org.apereo.cas.ticket.support.MultiTimeUseOrTimeoutExpirationPolicy] - <Ticket usage count 1 is greater than or equal to 1>
2016-09-20 11:32:41,051 DEBUG [org.apereo.cas.ticket.registry.DefaultTicketRegistry] - <Removing ticket [ST-1-gllwwWzqBYPDHOtacVpk-venus] from the registry.>
2016-09-20 11:32:41,052 DEBUG [org.apereo.cas.audit.spi.ThreadLocalPrincipalResolver] - <Resolving principal at audit point [execution(Assertion org.apereo.cas.CentralAuthenticationServiceImpl.validateServiceTicket(String,Service))]>
2016-09-20 11:32:41,071 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <Locating the primary authentication associated with this service request https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient>
2016-09-20 11:32:41,093 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <No particular authentication context is required for this request>
2016-09-20 11:32:41,093 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <No service credentials specified, and/or the proxy handler [org.apereo.cas.ticket.proxy.support.Cas20ProxyHandler@36aa8aa5] cannot handle credentials>
2016-09-20 11:32:41,094 DEBUG [org.apereo.cas.web.v3.V3ServiceValidateController] - <Successfully validated service ticket ST-1-gllwwWzqBYPDHOtacVpk-venus for service [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:41,097 DEBUG [org.apereo.cas.web.view.Cas30ResponseView] - <Preparing the output model to render view...>
2016-09-20 11:32:41,107 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <Starting to encode attributes for release to service [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:41,108 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[credential] is not available as a cached model attribute to encrypt...>
2016-09-20 11:32:41,108 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[proxyGrantingTicket] is not available as a cached model attribute to encrypt...>
2016-09-20 11:32:41,109 DEBUG [org.apereo.cas.authentication.support.DefaultCasAttributeEncoder] - <[5] Encoded attributes are available for release to [https://securedev.binghamton.edu/cas5-management/callback?client_name=CasClient]>
2016-09-20 11:32:41,113 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[false]]>
2016-09-20 11:32:41,114 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[true]]>
2016-09-20 11:32:41,115 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[2016-09-20T11:32:40.539-04:00[US/Eastern]]]>
2016-09-20 11:32:41,115 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting attribute [LdapAuthenticationHandler]>
2016-09-20 11:32:41,116 DEBUG [org.apereo.cas.util.CollectionUtils] - <Converting multi-valued attribute [[LdapAuthenticationHandler]]>
2016-09-20 11:32:41,164 DEBUG [org.jasig.cas.client.validation.Cas30ServiceTicketValidator] - <Server response: <cas:serviceResponse xmlns:cas="http://www.yale.edu/tp/cas"><cas:authenticationSuccess><cas:user>jramsay</cas:user>
<cas:attributes><cas:longTermAuthenticationRequestTokenUsed>false</cas:longTermAuthenticationRequestTokenUsed>
<cas:isFromNewLogin>true</cas:isFromNewLogin>
<cas:authenticationDate>2016-09-20T11:32:40.539-04:00[US/Eastern]</cas:authenticationDate>
<cas:authenticationMethod>LdapAuthenticationHandler</cas:authenticationMethod>
<cas:successfulAuthenticationHandlers>LdapAuthenticationHandler</cas:successfulAuthenticationHandlers>
</cas:attributes>
</cas:authenticationSuccess>
</cas:serviceResponse>
>
-Jeff
Misagh Moayyed
Sep 20, 2016, 1:50:42 PM9/20/16
to Jeffrey Ramsay, CAS Community
Yes, looks fine.
--
Misagh
Misagh
From: Jeffrey Ramsay <jeffrey...@gmail.com>
Reply: Jeffrey Ramsay <jeffrey...@gmail.com>
Date: September 20, 2016 at 8:29:13 PM
To: CAS Community <cas-...@apereo.org>
Subject: [cas-user] Re: CAS Management App 5.0.0.RC2-SNAPSHOT
--
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 post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/d2cd5831-3115-402c-83cb-ff193955d3e0%40apereo.org.
Jeffrey Ramsay
Sep 20, 2016, 3:29:07 PM9/20/16
to CAS Community
Do you have any idea why I still get Access Denied?
On Sunday, September 18, 2016 at 7:51:13 PM UTC-4, Jeffrey Ramsay wrote:
Jeffrey Ramsay
Sep 20, 2016, 3:58:18 PM9/20/16
to CAS Community
I found the problem and I'm able to access the console.
I tried to override the user-details.properties location by setting the following but it's clearly not working.
# user.details.file.location = classpath:user-details.properties
user.details.file.location=file:/etc/cas/5/dev/user-details.properties
-Jeff
I tried to override the user-details.properties location by setting the following but it's clearly not working.
# user.details.file.location = classpath:user-details.properties
user.details.file.location=file:/etc/cas/5/dev/user-details.properties
-Jeff
On Sunday, September 18, 2016 at 7:51:13 PM UTC-4, Jeffrey Ramsay wrote:
Misagh Moayyed
Sep 21, 2016, 1:36:25 PM9/21/16
to CAS Community
It most definitely won’t work, given that’s an invalid property. See:
From: cas-...@apereo.org [mailto:cas-...@apereo.org] On Behalf Of Jeffrey Ramsay
Sent: Tuesday, September 20, 2016 11:28 PM
To: CAS Community <cas-...@apereo.org>
Subject: [cas-user] Re: CAS Management App 5.0.0.RC2-SNAPSHOT
I found the problem and I'm able to access the console.
--
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 post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/bb241356-f071-492e-a274-281f149c3629%40apereo.org.
Jeffrey Ramsay
Sep 21, 2016, 1:58:18 PM9/21/16
to Misagh Moayyed, CAS Community
It's hard to tell what will or will not work. The definition I shared before was directly from the cas-management.properties file. Those lines should probably be removed to avoid confusion.
| # User details file location that contains list of users | |
| # who are allowed access to the management webapp: | |
| # |
| # user.details.file.location = classpath:user-details.properties | |
| ## | |
| # JSON Service Registry | |
| # | |
| # Directory location where JSON service files may be found. | |
| # service.registry.config.location=classpath:services | |
Thanks,
-Jeff
On Wed, Sep 21, 2016 at 1:36 PM, Misagh Moayyed <mmoa...@unicon.net> wrote:
It most definitely won’t work, given that’s an invalid property. See:
From: cas-...@apereo.org [mailto:cas-...@apereo.org] On Behalf Of Jeffrey Ramsay
Sent: Tuesday, September 20, 2016 11:28 PM
To: CAS Community <cas-...@apereo.org>
Subject: [cas-user] Re: CAS Management App 5.0.0.RC2-SNAPSHOT
I found the problem and I'm able to access the console.
I tried to override the user-details.properties location by setting the following but it's clearly not working.
# user.details.file.location = classpath:user-details.properties
user.details.file.location=file:/etc/cas/5/dev/user-details.properties
-Jeff
On Sunday, September 18, 2016 at 7:51:13 PM UTC-4, Jeffrey Ramsay wrote:I'm receiving this message "You are not authorized to access this resource. Contact your CAS administrator for more info." while trying to access the CAS management interface. I have tried using the "casuser" account along with my LDAP credentials but both accounts have failed. I tried adding my LDAP userid to the user-details.properties file but that too has been unsuccessful.
Has anyone been able to authenticate using LDAP as user store and the user-default.properties file to limit admin access? I tried the "cas.mgmt" options but that too has not been successful.
-Jeff
--
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+unsubscribe@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/bb241356-f071-492e-a274-281f149c3629%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
--
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+unsubscribe@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/00b501d2142e%24a4741d90%24ed5c58b0%24%40unicon.net.
Misagh Moayyed
Sep 21, 2016, 2:09:38 PM9/21/16
to CAS Community
You’re perfectly right. Created https://github.com/apereo/cas-services-management-overlay/issues/4
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
To post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/bb241356-f071-492e-a274-281f149c3629%40apereo.org.
For more options, visit https://groups.google.com/a/apereo.org/d/optout.
--
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 post to this group, send email to cas-...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/cas-user/.
Marco Osorio
Jun 7, 2017, 5:43:26 AM6/7/17
to CAS Community
Hi,
Which solution did you find?
I have the users in user-details.properties but apparently do not load them correctly from the /opt/applications/cas-management/conf/ path, it is not the standard /etc/cas/config.
Thanks in advance
...
Juan Quintanilla
Sep 4, 2018, 4:48:42 PM9/4/18
to CAS Community
Hi,
We recently encountered an interesting issue with our CAS Implementation, in a few rare cases we have had some users report when logging into a client application (Canvas) they were logged in as another user In brief User A attempts to login with auto saved password and user B was also logging in around same time as user A. When user A is logged in they see Users B information.
After taking a look at the audit logs we noticed that when User A was logging in there was no Login entry they were given a Service ticket with their IP and user B username as if they had already authenticated. User B we did see the login authentication and ST and TGT ticket created under their IP, but we later saw that the TGT was destroyed under user A ip. Also looking in the access logs I found that for this particular case the 2 users had the same JSESSIONID.
99-109-76-128.lightspeed.miamfl.sbcglobal.net - - [02/Sep/2018:12:20:27 -0400] "GET /cas/login?service=https%3A%2F%2Ffiu.instructure.com%2Flogin%2Fcas HTTP/1.1" 200 5830
99-109-76-128.lightspeed.miamfl.sbcglobal.net - - [02/Sep/2018:12:20:27 -0400] "GET /cas/themes/olcanvas1/app.js HTTP/1.1" 200 526
99-109-76-128.lightspeed.miamfl.sbcglobal.net - - [02/Sep/2018:12:20:27 -0400] "GET /cas/themes/olcanvas1/cas.css HTTP/1.1" 200 8796
99-109-76-128.lightspeed.miamfl.sbcglobal.net - - [02/Sep/2018:12:20:27 -0400] "GET /cas/themes/olcanvas1/images/fiu_logo.png HTTP/1.1" 200 12186
99-109-76-128.lightspeed.miamfl.sbcglobal.net - - [02/Sep/2018:12:20:28 -0400] "GET /cas/favicon.ico;jsessionid=0C6DC0B7927A4024EFA762D90E1BCF69 HTTP/1.1" 200 3262
c-98-254-138-84.hsd1.fl.comcast.net - - [02/Sep/2018:12:20:30 -0400] "POST /cas/login;jsessionid=0C6DC0B7927A4024EFA762D90E1BCF69?service=https%3A%2F%2Ffiu.instructure.com%2Flogin%2Fcas HTTP/1.1"
302 -
- - - [31/Dec/1969:18:59:59 -0500] "-" 505 -
So my question would be what might cause this to happen? Could the fact that they had the same jsessionid cause the use to login as the other user?
___________________
Juan Quintanilla
Juan Quintanilla
Juan Quintanilla
Sep 5, 2018, 1:30:56 PM9/5/18
to CAS Community
Hi,
We are running CAS 3.6 with tomcat 8 and in some instances when 2 users are logging in user A is logged in as User B on the client application. So the session information for the first user ends up being used.
We noticed that in the tomcat access logs both users shared the same Jsessionid. It appears that a unique Jsessionid was not generated for the second user when they arrived on the login page.
Has anyone encountered a similar issue? If so any suggestions.
Thanks!
___________________
Juan Quintanilla
Juan Quintanilla
Andrew Marker
Sep 5, 2018, 8:24:03 PM9/5/18
to CAS Community
We had a similar issue with a service that was behind a load balancer. I Benito@Unicon helped to identify the issue. The IP address of the client is used in the generation of the session ID. Once our service went to producion the volume of requests was great and the pool of IDs was limited by the narrowed pool. So randomly, two users would use one session.
I don't know if that is the problem here, but, it is a great cautionary tale of not...
Ray Bon
Sep 6, 2018, 1:40:29 PM9/6/18
to cas-...@apereo.org
Juan,
The session id is managed by tomcat. If this happened once, then it could be chalked up to coincidence. But that does not sound like the case.
You might try tomcat forums.
In the mean time you could try changing jsessionid to something else (jsessionidcas) to avoid potential conflicts with other tomcat sessions. (All CAS servers in the cluster need the same setting.)
It can be set in application's web.xml or in tomcat, see https://tomcat.apache.org/tomcat-7.0-doc/config/context.html#Common_Attributes.
Ray
-- Ray Bon Programmer analyst Development Services, University Systems 2507218831 | CLE 019 | rb...@uvic.ca
Reply all
Reply to author
Forward
0 new messages