How to configure ldaptive (via jaas) to use connection pooling

273 views

Skip to first unread message

William Geoghegan

unread,

Sep 13, 2019, 10:46:18 AM9/13/19

to ldaptive

We have an application (that runs on Windows) that uses ldap to authenticate users. We are using ldaptive as our ldap client and we are configuring it via a jaas login configuration file. Over time we have started having problems where users cannot be authenticated. In our case, the problems crop up during our integration tests which exercise our Rest API. I don't have a good count for how many authentications we attempt during those tests, but I'm sure it is on the order of thousands.

Anyway, when I searched to see if other people had experienced similar problems, I came across this issue in the Confluence knowledge base:

https://confluence.atlassian.com/confkb/ldap-queries-fail-with-address-already-in-use-error-222201829.html

In case that link goes bad, the reported issue is that sometimes users fail to be authenticated and errors like this are reported in their log file:

2010-08-10 13:04:18,277 ERROR [http-80-8] [user.impl.ldap.LDAPUserManagerReadOnly] getUser Error retrieving user: 'Husein.Alatas' from LDAP.
 -- url: /display/Test | userName: Husein.Alatas | referer: http://confluence/display/dashboard/Home | action: notpermitted
com.atlassian.user.impl.ldap.repository.LdapConnectionFailedException: javax.naming.CommunicationException: ldap.atlassian.com:389 [Root exception is java.net.BindException: Address already in use: connect]
    at com.atlassian.user.impl.ldap.repository.DefaultLdapContextFactory.getLDAPContext(DefaultLdapContextFactory.java:93)
    at com.atlassian.user.impl.ldap.search.DefaultLDAPUserAdaptor.search(DefaultLDAPUserAdaptor.java:70)
    at com.atlassian.user.impl.ldap.search.DefaultLDAPUserAdaptor.search(DefaultLDAPUserAdaptor.java:54)
    at com.atlassian.user.impl.ldap.LDAPUserManagerReadOnly.getUser(LDAPUserManagerReadOnly.java:70)
    at com.atlassian.user.impl.delegation.DelegatingUserManager.getUser(DelegatingUserManager.java:68)
    at bucket.user.DefaultUserAccessor.getUser(DefaultUserAccessor.java:146)
...
Caused by: javax.naming.CommunicationException: ldap.atlassian.com:389 [Root exception is java.net.BindException: Address already in use: connect]
    at com.sun.jndi.ldap.Connection.<init>(Connection.java:200)
    at com.sun.jndi.ldap.LdapClient.<init>(LdapClient.java:118)
    at com.sun.jndi.ldap.LdapClientFactory.createPooledConnection(LdapClientFactory.java:46)
    at com.sun.jndi.ldap.pool.Connections.getOrCreateConnection(Connections.java:185)
...
Caused by: java.net.BindException: Address already in use: connect
    at java.net.PlainSocketImpl.socketConnect(Native Method)
...

We are seeing similar CommunicationException and BindException in our server log.

The Confluence support link suggests running this command:

netstat -na

To see if there are a lot of connections from the application server to the ldap server. In our case, I am seeing hundreds or thousands of entries like this:

TCP 129.135.249.138:65523 129.135.28.18:10389 ESTABLISHED

TCP 129.135.249.138:65524 129.135.28.18:10389 ESTABLISHED

TCP 129.135.249.138:65525 129.135.28.18:10389 ESTABLISHED

TCP 129.135.249.138:65526 129.135.28.18:10389 ESTABLISHED

TCP 129.135.249.138:65527 129.135.28.18:10389 ESTABLISHED

TCP 129.135.249.138:65528 129.135.28.18:10389 ESTABLISHED

Where the left address is our application server:port and the right address is our ldap server:port. Our appication ports go all the way up to 65535.

The Confluence support link suggests that turning on ldap cachine should help.

Our application is not Confluence and our application does not have anything to do with Confluence, but I used the information from their knowledge base to refine my search and found that ldaptive supports connection pooling, as described here:

https://www.ldaptive.org/docs/guide/jaas.html

Unfortunately, I have not been able to get this to work.

Before I started looking into this problem, our ldaptive jaas configuration looked something like this:

ourApplication {
  org.ldaptive.jaas.LdapLoginModule required
    storePass="true"
    ldapUrl="ldap://ldapserver:10389"
    baseDn="ou=People,dc=example,dc=com"
    useStartTLS="false"
    bindDn="uid=admin,ou=People,dc=example,dc=com"
    bindCredential="password"
    userFilter="(uid={user})";
  org.ldaptive.jaas.LdapRoleAuthorizationModule required
    useFirstPass="true"
    ldapUrl="ldap://ldapserver:10389"
    baseDn="ou=Roles,dc=example,dc=com"
    roleFilter="(member={dn})"
    roleAttribute="cn";
};

This works, users are authenticated, and get can get roles for users.

The example of connection pool configuration from the ldaptive link above looks like this:

ldaptive {
  org.ldaptive.jaas.LdapLoginModule required
    ldapUrl="ldap://directory.ldaptive.org:389"
    baseDn="ou=people,dc=ldaptive,dc=org"
    bindDn="cn=priviledged_user,ou=services,dc=vt,dc=edu"
    bindCredential="notarealpassword"
    useStartTLS="true"
    userFilter="(uid={user})"
    userRoleAttribute="eduPersonAffiliation"
    dnResolver="org.ldaptive.auth.SearchDnResolver"
    authenticationHandler="org.ldaptive.auth.SimpleBindAuthenticationHandler"
    connectionFactory="org.ldaptive.PooledConnectionFactory"
    cacheId="ldaptive-pooled";
};

I tried to use that as a model to update our ldap jaas configuration, but have not gotten it to work. I have found at least two problems. First, there is no SimpleBindAuthenticationHandler class. The closest seems to be BindAuthenticationHandler. Second, the fully qualified name for PooledConnectionFactory should be (based on examining the ldaptive.jar contents) org.ldaptive.pool.PooledConnectionFactory.

With all that in mind, this is what I came up:

ourApplication {
  org.ldaptive.jaas.LdapLoginModule required
    storePass="true"
    ldapUrl="ldap://ldapserver:10389"
    baseDn="ou=People,dc=example,dc=com"
    useStartTLS="false"
    bindDn="uid=admin,ou=People,dc=example,dc=com"
    bindCredential="password"
    userFilter="(uid={user})"
    dnResolver="org.ldaptive.auth.SearchDnResolver"
    authenticationHandler="org.ldaptive.auth.BindAuthenticationHandler"
    connectionFactory="org.ldaptive.pool.PooledConnectionFactory"
    cacheId="ldaptive-pooled";
  org.ldaptive.jaas.LdapRoleAuthorizationModule required
    useFirstPass="true"
    ldapUrl="ldap://ldapserver:10389"
    baseDn="ou=Roles,dc=example,dc=com"
    roleFilter="(member={dn})"
    roleAttribute="cn";
};

Now, when I run our application and try to authenticate, authentication fails and I see this error in our log file:

2019-09-12 14:45:10,229 ERROR (ajp-nio-8009-exec-3)[org.ldaptive.props.AbstractPropertyInvoker] Error invoking public void org.ldaptive.auth.SearchDnResolver.setConnectionFactory(org.ldaptive.ConnectionFactory), on [org.ldaptive.auth.SearchDnResolver@1036972035::factory=null, baseDn=, userFilter=null, userFilterParameters=null, allowMultipleDns=false, subtreeSearch=false, derefAliases=null, referralHandler=null], with params org.ldaptive.pool.PooledConnectionFactory

Final questions:

1. Our original problem seems to be due to ldaptive opening connections from our application server to the ldap server and leaving them open. Does that sound right?

2. Should configuring ldaptive to use connection pooling work?

3. If connection pooling works, is there a good chance it will solve our problem?

Our application, as currently deployed, is using ldaptive 1.1.0, but I have tried with ldaptive 1.2.4 and could not get the connection pooling to work with it either.

Thanks for any help.

William Geoghegan

unread,

Sep 13, 2019, 12:00:10 PM9/13/19

to ldaptive

A little more from our server log with ldaptive.jaas logging turned up to TRACE:

2019-09-12 16:41:05,778 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapLoginModule] Begin initialize
2019-09-12 16:41:05,778 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapLoginModule] useFirstPass = false, tryFirstPass = false, storePass = true, clearPass = false, setLdapPrincipal = true, setLdapDnPrincipal = false, setLdapCredential = true, defaultRole = [], principalGroupName = null, roleGroupName = null
2019-09-12 16:41:05,778 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapLoginModule] authenticatorFactory = org.ldaptive.jaas.PropertiesAuthenticatorFactory@384ba648, userRoleAttribute = [1.1]
2019-09-12 16:41:05,811 ERROR (ajp-nio-8009-exec-3)[org.ldaptive.props.AbstractPropertyInvoker] Error invoking public void org.ldaptive.auth.SearchDnResolver.setConnectionFactory(org.ldaptive.ConnectionFactory), on [org.ldaptive.auth.SearchDnResolver@1317010164::factory=null, baseDn=, userFilter=null, userFilterParameters=null, allowMultipleDns=false, subtreeSearch=false, derefAliases=null, referralHandler=null], with params org.ldaptive.pool.PooledConnectionFactory
2019-09-12 16:41:05,811 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] Begin initialize
2019-09-12 16:41:05,811 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] useFirstPass = true, tryFirstPass = false, storePass = false, clearPass = false, setLdapPrincipal = false, setLdapDnPrincipal = false, setLdapCredential = false, defaultRole = [], principalGroupName = null, roleGroupName = null
2019-09-12 16:41:05,811 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] roleResolverFactory = org.ldaptive.jaas.PropertiesRoleResolverFactory@65816d21, roleFilter = (member={dn}), roleAttribute = [cn], noResultsIsError = false
2019-09-12 16:41:05,842 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.PropertiesRoleResolverFactory] Created role resolver [org.ldaptive.jaas.SearchRoleResolver@52239159::factory=[org.ldaptive.DefaultConnectionFactory@465296480::provider=org.ldaptive.provider.jndi.JndiProvider@31e6d869, config=[org.ldaptive.ConnectionConfig@997203428::ldapUrl=ldap://heliosvmlt2:10389, connectTimeout=null, responseTimeout=null, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50df7d1e]]] from {ldapUrl=ldap://heliosvmlt2:10389, roleAttribute=cn, baseDn=ou=Roles,dc=example,dc=com, roleFilter=(member={dn}), useFirstPass=true}
2019-09-12 16:41:05,842 DEBUG (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] Retrieved role resolver from factory: [org.ldaptive.jaas.SearchRoleResolver@52239159::factory=[org.ldaptive.DefaultConnectionFactory@465296480::provider=org.ldaptive.provider.jndi.JndiProvider@31e6d869, config=[org.ldaptive.ConnectionConfig@997203428::ldapUrl=ldap://heliosvmlt2:10389, connectTimeout=null, responseTimeout=null, sslConfig=null, useSSL=false, useStartTLS=false, connectionInitializer=null, connectionStrategy=org.ldaptive.DefaultConnectionStrategy@50df7d1e]]]
2019-09-12 16:41:05,857 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.PropertiesRoleResolverFactory] Created search request [org.ldaptive.SearchRequest@-1773143324::baseDn=ou=Roles,dc=example,dc=com, searchFilter=null, returnAttributes=[], searchScope=SUBTREE, timeLimit=PT0S, sizeLimit=0, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, referralHandler=null, intermediateResponseHandlers=null] from {ldapUrl=ldap://heliosvmlt2:10389, roleAttribute=cn, baseDn=ou=Roles,dc=example,dc=com, roleFilter=(member={dn}), useFirstPass=true}
2019-09-12 16:41:05,857 DEBUG (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] Retrieved search request from factory: [org.ldaptive.SearchRequest@-1939986723::baseDn=ou=Roles,dc=example,dc=com, searchFilter=null, returnAttributes=[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]
2019-09-12 16:41:05,857 TRACE (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] Begin getCredentials: useFistPass = true, tryFistPass = false, useCallback = false, callbackhandler class = javax.security.auth.login.LoginContext$SecureCallbackHandler, name callback class = javax.security.auth.callback.NameCallback, password callback class = javax.security.auth.callback.PasswordCallback
2019-09-12 16:41:05,904 DEBUG (ajp-nio-8009-exec-3)[org.ldaptive.jaas.LdapRoleAuthorizationModule] Error occurred attempting role lookup
[org.ldaptive.LdapException@416549198::resultCode=ALIAS_DEREFERENCING_PROBLEM, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=javax.naming.NamingException: [LDAP: error code 36 - ALIAS_DEREFERENCING_PROBLEM: failed for MessageType : SEARCH_REQUEST
Message ID : 1
    SearchRequest
        baseDn : 'ou=Roles,dc=example,dc=com'
        filter : '(member={dn})'
        scope : whole subtree
        typesOnly : false
        Size Limit : no limit
        Time Limit : no limit
        Deref Aliases : never Deref Aliases
        attributes : 'cn'
org.apache.directory.api.ldap.model.message.SearchRequestImpl@166a3ab: java.lang.IllegalArgumentException: ERR_13247_INVALID_VALUE_CANT_NORMALIZE Invalid upValue, it cant be normalized]; remaining name 'ou=Roles,dc=example,dc=com', providerException=javax.naming.NamingException: [LDAP: error code 36 - ALIAS_DEREFERENCING_PROBLEM: failed for MessageType : SEARCH_REQUEST
Message ID : 1
    SearchRequest
        baseDn : 'ou=Roles,dc=example,dc=com'
        filter : '(member={dn})'
        scope : whole subtree
        typesOnly : false
        Size Limit : no limit
        Time Limit : no limit
        Deref Aliases : never Deref Aliases
        attributes : 'cn'
org.apache.directory.api.ldap.model.message.SearchRequestImpl@166a3ab: java.lang.IllegalArgumentException: ERR_13247_INVALID_VALUE_CANT_NORMALIZE Invalid upValue, it cant be normalized]; remaining name 'ou=Roles,dc=example,dc=com']
 at org.ldaptive.provider.ProviderUtils.throwOperationException(ProviderUtils.java:55)
 at org.ldaptive.provider.jndi.JndiConnection.processNamingException(JndiConnection.java:619)
 at org.ldaptive.provider.jndi.JndiConnection$JndiSearchIterator.initialize(JndiConnection.java:741)
 at org.ldaptive.provider.jndi.JndiConnection.search(JndiConnection.java:463)
 at org.ldaptive.SearchOperation.executeSearch(SearchOperation.java:103)
 at org.ldaptive.SearchOperation.invoke(SearchOperation.java:85)
 at org.ldaptive.SearchOperation.invoke(SearchOperation.java:15)
 at org.ldaptive.AbstractOperation.execute(AbstractOperation.java:126)
 at org.ldaptive.jaas.AbstractSearchRoleResolver.search(AbstractSearchRoleResolver.java:29)
 at org.ldaptive.jaas.LdapRoleAuthorizationModule.login(LdapRoleAuthorizationModule.java:128)
 at org.ldaptive.jaas.AbstractLoginModule.login(AbstractLoginModule.java:165)

William Geoghegan

unread,

Sep 13, 2019, 5:11:02 PM9/13/19

to ldaptive

After reading the this forum in more detail, I did find an example that allowed me to create a jaas configuration that specifies pooling. I can see that it is working in the log because I can see messages like "Retrieved authenticator from CACHE" and "Retrieved role resolver from CACHE".

My configuration now looks like this:

ourApplication {
  org.ldaptive.jaas.LdapLoginModule required
    storePass="true"
    ldapUrl="ldap://ldapserver:10389"
    baseDn="ou=People,dc=example,dc=com"
    useStartTLS="false"
    bindDn="uid=admin,ou=People,dc=example,dc=com"
    bindCredential="password"
    userFilter="(uid={user})"


    dnResolver="org.ldaptive.auth.PooledSearchDnResolver"
    authenticationHandler="org.ldaptive.auth.PooledBindAuthenticationHandler"
    pruneStrategy="org.ldaptive.pool.IdlePruneStrategy{{prunePeriod=PT3M}{idleTime=PT6M}}"
    cacheId="ldaptive-users-pooled";


  org.ldaptive.jaas.LdapRoleAuthorizationModule required
    useFirstPass="true"
    ldapUrl="ldap://ldapserver:10389"
    baseDn="ou=Roles,dc=example,dc=com"
    roleFilter="(member={dn})"
    roleAttribute="cn"


    dnResolver="org.ldaptive.auth.PooledSearchDnResolver"
    authenticationHandler="org.ldaptive.auth.PooledBindAuthenticationHandler"
    pruneStrategy="org.ldaptive.pool.IdlePruneStrategy{{prunePeriod=PT3M}{idleTime=PT6M}}"
    cacheId="ldaptive-roles-pooled";
};

Note that I had to use ldaptive 1.2.4 for the pruneStrategy configuration to work (ie to not result in errors authenticating in the log file).

I'm not sure I am seeing a huge difference in the results of the netstat -na command. Here is part of the output of that command over an hour after I completed a short test run:

  TCP    129.135.28.210:61192   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61217   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61222   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61224   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61226   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61228   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61230   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61232   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61234   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61237   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61240   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61242   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61244   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61250   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61252   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61254   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61256   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61258   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61260   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61262   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61264   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61269   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61271   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61273   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61275   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61277   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61279   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61281   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61283   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61285   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61288   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61290   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61292   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61294   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61299   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61301   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61303   129.135.28.18:10389    ESTABLISHED
  TCP    129.135.28.210:61309   129.135.28.18:10389    ESTABLISHED

I was hoping that, by using the pooling and defining a pruning strategy, the connections from the application server to the ldap server would eventually go back to zero. It is interesting to note that about every other port number is in use in this example of netstat -na output vs when I first started investigating this when every port number (on the application server) was in use.

Small sample of netstat -na prior to my adding the pooling and pruning configuration:

  TCP    129.135.249.30:49719   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49720   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49721   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49722   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49723   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49724   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49725   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49726   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49727   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49728   129.135.28.194:10389   ESTABLISHED
  TCP    129.135.249.30:49729   129.135.28.194:10389   ESTABLISHED

So, the pooling and/or pruning is having some effect on the number of connections. But I don't understand why the connections continue to persist long after any ldap activity, even with the pooling and pruning settings.

Finally, the ldaptive-props example here: https://github.com/vt-middleware/ldaptive/blob/master/integration/src/test/resources/ldap_jaas.config seems to have a syntax error in the pruneStrategy section. It is missing a closing brace.

Questions:

1. Should the connections from the application server to the ldap server disappear after some amount of inactivity?

2. Why would some connections, apparently, go away but not all? Looking at the first netstat -na output in this post, we can see that there is usually a gap of one port in use, and sometimes a gap of 2, 3, 4 ports or more.

I have not run the full test suite with the new configuration and ldaptive 1.2.4, but I plan to. It will be interesting to see if it completes.

Thanks for any help.

William Geoghegan

unread,

Sep 17, 2019, 2:50:33 PM9/17/19

to ldaptive

I found the OpenJDK bug under Issues:

https://github.com/vt-middleware/ldaptive/issues/148

Someone on StackOverflow posted a solution my issue using UnboundID (as mentined in the link above):

https://stackoverflow.com/questions/57914310/how-to-configure-ldaptive-to-use-connection-pooling-jaas/57936168#57936168