CAS 5.2/5.3 cas.util.LdapUtils try connect to localhost for LDAP

[mohsen saeedi]

Hi

I have experience more than 7 years on apereo CAS. after we updated our cas overlay version to 5.2.3 (test with 5.3.6 too) one problem occur during tomcat starting. 

We define ldapUrl, bindDn, bindCredential in cas configuration file. this config was working for older build (with 5.2.2 version). I think the problem is caused by poolPassivator has been added to overlay (maybe after 5.1RC2). in this environment oldest build everything works like charms. 

however we enabled debugging for cas.util.LdapUtils and restart tomcat. on ldap initialization cas.util.LdapUtils try connect to our ldapUrl. sample log:

Jul 30 11:24:25 SSO1 server[4213]: 2020-07-30 11:24:25,594 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP bind connection initializer via [cn=manager,dc=domain]>

Jul 30 11:24:25 SSO1 server[4213]: 2020-07-30 11:24:25,595 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection pool configuration for [ldap://192.168.xxx.71:389 ldap://ldap.xxx.local:389]>

Jul 30 11:24:25 SSO1 server[4213]: 2020-07-30 11:24:25,582 DEBUG [org.apereo.cas.util.LdapUtils] - <Initializing ldap connection pool for [ldap://192.168.xxx.71:389 ldap://ldap.xxx.local:389] and bindDn [cn=manager,dc=domain]>

but after this logs, cas.util.LdapUtils try connect to localhost:389

Jul 30 11:24:40 SSO1 server[4213]: 2020-07-30 11:24:40,240 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection factory for [ldap://localhost:389]>

Jul 30 11:24:40 SSO1 server[4213]: 2020-07-30 11:24:40,242 WARN [org.apereo.cas.util.LdapUtils] - <No [BIND] passivator could be created for [ldap://localhost:389] given bind credentials are not specified>

Jul 30 11:24:40 SSO1 server[4213]: 2020-07-30 11:24:40,315 ERROR [org.ldaptive.pool.BlockingConnectionPool]

cas.authn.ldap[0].LdapUrl=ldap://192.168.xxx.71:389 ldap://ldap.xxx.local:389

cas.authn.ldap[0].type=AUTHENTICATED

cas.authn.ldap[0].bindDn=cn=manager,dc=domain

cas.authn.ldap[0].bindCredential=ldap_manager_password

# Bind credentials used to connect to the LDAP instance

#

cas.authn.ldap[0].poolPassivator=NONE

cas.authn.ldap[0].connectionStrategy=DEFAULT

cas.authn.ldap[0].useSsl=false

cas.authn.ldap[0].useStartTls=false

# cas.authn.ldap[0].connectTimeout=5000

cas.authn.ldap[0].subtreeSearch=true

cas.authn.ldap[0].minPoolSize=0

cas.authn.ldap[0].maxPoolSize=10

I use CLOSE and BIND for passivator to test. what is the problem? when we switch back to our oldest cas (5.2.2 built with older ldaptive library) it starts without any problem. all config and ldap services are fixed during the test. 

[Daniel Fisher]

On Thu, Jul 30, 2020 at 3:23 AM mohsen saeedi <mohsen...@gmail.com> wrote:

Jul 30 11:24:40 SSO1 server[4213]: 2020-07-30 11:24:40,315 ERROR [org.ldaptive.pool.BlockingConnectionPool]

What error is reported here?

--Daniel Fisher

[mohsen saeedi]

The problem occur when it try to connect to ldap and finally failed to start. for example i defined 192.168.250.71 as ldapUrl but it try to connect to localhost! 

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,797 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection factory for [ldap://localhost:389]>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,797 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection configuration for [ldap://localhost:389]>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,798 DEBUG [org.apereo.cas.util.LdapUtils] - <Transformed LDAP urls from [ldap://localhost:389] to [ldap://localhost:389]>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,798 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP SSL configuration via the native JVM truststore>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,798 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection pool configuration for [ldap://localhost:389]>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,799 WARN [org.apereo.cas.util.LdapUtils] - <No [BIND] passivator could be created for [ldap://localhost:389] given bind credentials are not specified>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,799 DEBUG [org.apereo.cas.util.LdapUtils] - <Initializing ldap connection pool for [ldap://localhost:389] and bindDn [null]>

Jul 30 20:58:38 SSO1 server[10311]: 2020-07-30 20:58:38,872 ERROR [org.ldaptive.pool.BlockingConnectionPool] - <[org.ldaptive.pool.BlockingConnectionPool@1048947778::name=null, poolConfig=[org.ldaptive.pool.PoolConfig@562606106::minPoolSize=3, maxPoolSize=10, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=true, validatePeriod=PT5M, validateTimeout=PT5S], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator@432073790::searchRequest=[org.ldaptive.SearchRequest@-1800458700::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=[org.ldaptive.referral.SearchReferralHandler$SearchReferenceHandler@4a664d6], controls=null, referralHandler=org.ldaptive.referral.SearchReferralHandler@6d01e679, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy@1513537499::prunePeriod=PT2H, idleTime=PT10M], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory@1545585902::provider=org.ldaptive.provider.jndi.JndiProvider@5d097df4, config=[org.ldaptive.ConnectionConfig@1062824450::ldapUrl=ldap://localhost:389, connectTimeout=PT5S, responseTimeout=PT5S, sslConfig=[org.ldaptive.ssl.SslConfig@1358873173::credentialConfig=null, trustManagers=null, hostnameVerifier=null, hostnameVerifierConfig=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@72644410]], initialized=false, availableCount=0, activeCount=0] unable to connect to the ldap>

Jul 30 20:58:38 SSO1 server[10311]: org.ldaptive.provider.ConnectionException: javax.naming.CommunicationException: localhost:389 [Root exception is java.net.ConnectException: Connection refused (Connection refused)]

but before this error CAS try to create LDAP connection factory to 192.168.250.71. here is logs:

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,703 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating authenticated authenticator for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,704 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection factory for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,704 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection configuration for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,708 DEBUG [org.apereo.cas.util.LdapUtils] - <Transformed LDAP urls from [ldap://192.168.250.71:389] to [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,708 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP SSL configuration via the native JVM truststore>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,710 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP bind connection initializer via [cn=manager,dc=uast,dc=ac,dc=ir]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,723 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection pool configuration for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,743 DEBUG [org.apereo.cas.util.LdapUtils] - <Initializing ldap connection pool for [ldap://192.168.250.71:389] and bindDn [cn=manager,dc=uast,dc=ac,dc=ir]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,751 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection factory for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,751 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection configuration for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,751 DEBUG [org.apereo.cas.util.LdapUtils] - <Transformed LDAP urls from [ldap://192.168.250.71:389] to [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,752 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP SSL configuration via the native JVM truststore>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,752 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP bind connection initializer via [cn=manager,dc=uast,dc=ac,dc=ir]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,752 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection pool configuration for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,753 DEBUG [org.apereo.cas.util.LdapUtils] - <Initializing ldap connection pool for [ldap://192.168.250.71:389] and bindDn [cn=manager,dc=uast,dc=ac,dc=ir]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,764 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection factory for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,764 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection configuration for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,765 DEBUG [org.apereo.cas.util.LdapUtils] - <Transformed LDAP urls from [ldap://192.168.250.71:389] to [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,765 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP SSL configuration via the native JVM truststore>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,765 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP bind connection initializer via [cn=manager,dc=uast,dc=ac,dc=ir]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,766 DEBUG [org.apereo.cas.util.LdapUtils] - <Creating LDAP connection pool configuration for [ldap://192.168.250.71:389]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,766 DEBUG [org.apereo.cas.util.LdapUtils] - <Initializing ldap connection pool for [ldap://192.168.250.71:389] and bindDn [cn=manager,dc=uast,dc=ac,dc=ir]>

Jul 30 20:58:24 SSO1 server[10311]: 2020-07-30 20:58:24,862 WARN [org.apereo.cas.support.pac4j.config.support.authentication.Pac4jAuthenticationEventExecutionPlanConfiguration] - <No delegated authentication clients are defined/configured>

CAS version is 5.2.2 . it works with this same version that was built two years ago. I know something has been updated on CAS code for ldaptive poolPassivator. 

[mohsen saeedi]

I think i added cas-server-support-ldap-service-registry as dependency. and i don't have any configuration parameter for that on cas.properties. maybe the problem caused for that!!! I will test again and send result here

[mohsen saeedi]

The problem solved! with remove cas-server-support-ldap-service-registry from pom.xml