Issue with LDAP authentication: LDAP response read timed out
1,331 views
Skip to first unread message
David Hübner
Jun 22, 2017, 9:18:40 AM6/22/17
to CAS Community
Hi all,
During start up of Tomcat the CAS server initializes a connection pool.
So in total there are 9 BindRequests+Responses during initialization. When looking at the LDAP server's logs I can also verify 9 BIND requests. So everything works as expected.
When looking at the LDAP server's logs I also do not see anything. It's like the request never leaves the server that is running CAS.
we want to deploy a CAS 5.1 server with the Maven Overlay method under Cent OS7, Java 1.8.0 and Tomcat 8.0.
Currently I am trying to set up authentication against LDAP.
The configuration I am using is fairly simple:
cas.authn.ldap[0].type=AUTHENTICATED
cas.authn.ldap[0].useSsl=false
cas.authn.ldap[0].ldapUrl=ldap://...:3890
cas.authn.ldap[0].bindDn=cn=manager,dc=example,dc=org
cas.authn.ldap[0].bindCredential=secret
cas.authn.ldap[0].baseDn=dc=example,dc=org
cas.authn.ldap[0].userFilter=uid={user}
cas.authn.ldap[0].subtreeSearch=true
During start up of Tomcat the CAS server initializes a connection pool.
In the log there are three consecutive
beginning pool initialization...
...
execute request=[org.ldaptive.BindRequest@261320823...
execute response=[org.ldaptive.Response@753570317...
[request and response happens 2 more times here]
added available connection: org.ldaptive.pool.AbstractConnectionPool
So in total there are 9 BindRequests+Responses during initialization. When looking at the LDAP server's logs I can also verify 9 BIND requests. So everything works as expected.
Fast forward to authentication. There is a timeout when reading the LDAP response. So essentially there never is a response. See the log below for this part:
2017-06-22 15:07:13,564 DEBUG [org.ldaptive.SearchOperation] - <execute request=[org.ldaptive.SearchRequest@1990922963::baseDn=dc=example,dc=org, searchFilter=[org.ldaptive.SearchFilter@538592870::filter=uid={user}, parameters={context=null, user=t.benutzer}], returnAttributes=[1.1], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection@1341165364::config=[org.ldaptive.ConnectionConfig@1707652548::ldapUrl=ldap://openldap-1.daasi.prj:3890, connectTimeout=PT5S, responseTimeout=PT5S, sslConfig=[org.ldaptive.ssl.SslConfig@215657008::credentialConfig=null, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitializer=[org.ldaptive.BindConnectionInitializer@983570221::bindDn=cn=manager,dc=example,dc=org, bindSaslConfig=null, bindControls=null], connectionStrategy=org.ldaptive.DefaultConnectionStrategy@36e4c967], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory@1968431256::metadata=[ldapUrl=ldap://openldap-1.daasi.prj:3890, count=1], environment={com.sun.jndi.ldap.connect.timeout=5000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, com.sun.jndi.ldap.read.timeout=5000}, classLoader=null, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig@1701617828::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, controlProcessor=org.ldaptive.provider.ControlProcessor@622e959f, 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@296c3fc1]>2017-06-22 15:07:18,748 DEBUG [org.ldaptive.provider.jndi.NamingExceptionUtils] - <naming exception class javax.naming.NamingException is ambiguous, maps to multiple result codes: [OPERATIONS_ERROR, ALIAS_PROBLEM, ALIAS_DEREFERENCING_PROBLEM, LOOP_DETECT, AFFECTS_MULTIPLE_DSAS, OTHER]>2017-06-22 15:07:18,760 ERROR [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <[LdapAuthenticationHandler]: [Unexpected LDAP error] (Details: [javax.naming.NamingException: LDAP response read timed out, timeout used:5000ms.; remaining name 'dc=example,dc=org'])>2017-06-22 15:07:18,761 WARN [org.apereo.cas.authentication.PolicyBasedAuthenticationManager] - <Authentication has failed. Credentials may be incorrect or CAS cannot find authentication handler that supports [t.benutzer] of type [UsernamePasswordCredential], which suggests a configuration problem.>When looking at the LDAP server's logs I also do not see anything. It's like the request never leaves the server that is running CAS.
Now the funny thing is: when I restart the LDAP server now and try to login again it does work! Another bind occurs, since the connection is no longer available and I get a response to the SearchRequest. Obviously the LDAP server log does also reflect this and shows the search operation:
execute request=[org.ldaptive.SearchRequest@128569139
Operation exception encountered, reopening connection
...
execute request=[org.ldaptive.BindRequest@1701619972
execute response=[org.ldaptive.Response@844611484
execute response=[org.ldaptive.Response@430713277::result=[org.ldaptive.SearchResult
Authentication succeeded for dn: uid=t.benutzer,ou=people,dc=example,dc=org
I pretty much tried every timeout setting that is documented in https://apereo.github.io/cas/5.1.x/installation/Configuration-Properties.html and also played around with the Passivator settings.
When I set up an validator the same thing happens: there is no Response to the SearchRequests and in fact the LDAP server is never receiving any requests.
Any input on this is very much appreciated!
Daniel Fisher
Jun 22, 2017, 11:01:20 AM6/22/17
to cas-...@apereo.org
On Thu, Jun 22, 2017 at 9:18 AM, David Hübner <d.hue...@gmail.com> wrote:
Fast forward to authentication. There is a timeout when reading the LDAP response. So essentially there never is a response. See the log below for this part:
What does your pooling configuration look like?
--Daniel Fisher
David Hübner
Jun 22, 2017, 11:05:47 AM6/22/17
to CAS Community
What exactly are we talking about?
I have cas.authn.ldap[0].minPoolSize and maxPoolSize set to default, so 3/10.
Or are you talking about something else?
Daniel Fisher
Jun 22, 2017, 12:44:01 PM6/22/17
to cas-...@apereo.org
That's it, just wanted to make sure you're actually using a pool.
Can you post your complete configuration?
--Daniel Fisher
--
- CAS gitter chatroom: https://gitter.im/apereo/cas
- CAS mailing list guidelines: https://apereo.github.io/cas/Mailing-Lists.html
- CAS documentation website: https://apereo.github.io/cas
- CAS project website: https://github.com/apereo/cas
---
You received this message because you are subscribed to the Google Groups "CAS Community" group.
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+unsubscribe@apereo.org.
To view this discussion on the web visit https://groups.google.com/a/apereo.org/d/msgid/cas-user/b39f3769-4914-4bf9-a51a-bbb3b799ca5a%40apereo.org.
David Hübner
Jun 22, 2017, 3:08:00 PM6/22/17
to CAS Community
Well, there honestly is not that much there:
cas.server.name: ...cas.server.prefix: ...
logging.config: file:/etc/cas/config/log4j2.xmllogging.level.org.apereo=DEBUG
cas.authn.accept.users=
cas.authn.ldap[0].type=AUTHENTICATEDcas.authn.ldap[0].useSsl=falsecas.authn.ldap[0].ldapUrl=ldap://...:3890cas.authn.ldap[0].bindDn=...cas.authn.ldap[0].bindCredential=...cas.authn.ldap[0].baseDn=...cas.authn.ldap[0].userFilter=uid={user}
cas.authn.ldap[0].subtreeSearch=true
cas.authn.ldap[0].minPoolSize=3cas.authn.ldap[0].maxPoolSize=10cas.authn.ldap[0].idleTime=20000
cas.authn.ldap[0].validator.type=NONEcas.authn.ldap[0].validateOnCheckout=falsecas.authn.ldap[0].validatePeriodically=false
cas.authn.ldap[0].poolPassivator=NONE
cas.serviceRegistry.config.location: classpath:/servicesI built the WAR file with
<dependency> <groupId>org.apereo.cas</groupId> <artifactId>cas-server-support-ldap</artifactId> <version>${cas.version}</version></dependency>When I am really fast with my login attempt after starting Tomcat it actually works as well.
I figured that is what the idleTime setting is for and raised it, but apparently that's not true. If I wait even 1 minute after starting Tomcat I am unable to do anything and no SearchRequest ever reaches my LDAP server.
Sort of looks like the connections all timeout after some seconds, but no new connections are possible somehow.
If I set poolPassivator to CLOSE the error messages in the log actually change to "Connection closed". I can not give you the exact logs, because I do not have access to the server right now.
But still, I would expect a new connection, but apparently that never happens.
--Daniel Fisher
To unsubscribe from this group and stop receiving emails from it, send an email to cas-user+u...@apereo.org.
Daniel Fisher
Jun 22, 2017, 9:09:05 PM6/22/17
to cas-...@apereo.org
On Thu, Jun 22, 2017 at 3:08 PM, David Hübner <d.hue...@gmail.com> wrote:
You need to do some sort of validation to keep the pool healthy. I recommend you turn on periodic validation and then tweak the validate period for your environment.
--Daniel Fisher
Reply all
Reply to author
Forward
0 new messages