Pooled LdapTemplate stalls for minutes during context validation

Question

I'm trying to use Spring-ldap's LdapTemplate to retrieve information from an LDAP source during a Rest call service implementation and, while I think I have a working configuration, we're noticing stalls of up to 15 minutes intermittently when the service is hit. Logging statements have determined the stall happens during the ldapTemplate.search() call.

My beans:

    contextSourceTarget(org.springframework.ldap.core.support.LdapContextSource) {
        urls = ["https://someldapsource.com"]
        userDn = 'uid=someaccount,ou=xxx,cn=users,dc=org,dc=com'
        password = 'somepassword'
        pooled = true
    }
    dirContextValidator(org.springframework.ldap.pool2.validation.DefaultDirContextValidator)
    poolConfig( org.springframework.ldap.pool2.factory.PoolConfig ) {
        testOnBorrow = true
        testWhileIdle = true
    }
    ldapContextSource(org.springframework.ldap.pool2.factory.PooledContextSource, ref('poolConfig')) {
        contextSource = ref('contextSourceTarget')
        dirContextValidator = ref('dirContextValidator')
    }

    ldapTemplate(LdapTemplate, ref('ldapContextSource')) {}

I expect this application could be hitting LDAP several times concurrently (via concurrent rest calls to this app) for retrieving data from different users. Here's the code that makes that call:

    List attrs =['uid', 'otherattr1', 'otherattr2']
// this just returns a Map containing the key value pairs of the attrs passed in here.
    LdapNamedContextMapper mapper = new LdapNamedContextMapper( attrs ) 
    log.debug( "getLdapUser:preLdapSearch")
    List<Map> results = ldapTemplate.search( 
        'cn=grouproot,cn=Groups,dc=org,dc=com',
        'uniquemember=userNameImsearchingfor',
        SearchControls.SUBTREE_SCOPE, 
        attrs as String[], mapper )
    log.debug( "getLdapUser:postLdapSearch" )

Unfortunately, at random times it seems, the timestamp difference between the preLdapSearch and postLdapSearch logs is upwards of 15 minutes. Obviously, this is bad, and it would seem to be a pool management issue.

So I turned on debug logging for packages org.springframework.ldap and org.apache.commons.pool2

And now when this happens I get the following in the logs:

2018-09-20 20:18:46.251 DEBUG appEvent="getLdapUser:preLdapSearch"
2018-09-20 20:35:03.246 DEBUG  A class javax.naming.ServiceUnavailableException - not explicitly configured to be a non-transient exception - encountered; ignoring.
2018-09-20 20:35:03.249 DEBUG  DirContext 'javax.naming.ldap.InitialLdapContext@1f4f37b4' failed validation with an exception.
javax.naming.ServiceUnavailableException: my.ldaphost.com:636; socket closed
at com.sun.jndi.ldap.Connection.readReply(Connection.java:454)
at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638)
at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638)
at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:561)
at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985)
at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844)
at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1769)
at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:392)
(LOTS OF STACK TRACE REMOVED)
2018-09-20 20:35:03.249 DEBUG Closing READ_ONLY DirContext='javax.naming.ldap.InitialLdapContext@1f4f37b4'
2018-09-20 20:35:03.249 DEBUG Closed READ_ONLY DirContext='javax.naming.ldap.InitialLdapContext@1f4f37b4'
2018-09-20 20:35:03.249 DEBUG Creating a new READ_ONLY DirContext
2018-09-20 20:35:03.787 DEBUG Created new READ_ONLY DirContext='javax.naming.ldap.InitialLdapContext@5239386d'
2018-09-20 20:35:03.838 DEBUG DirContext 'javax.naming.ldap.InitialLdapContext@5239386d' passed validation.
2018-09-20 20:35:03.890 DEBUG appEvent="getLdapUser:postLdapSearch"

Questions:

How can I find out more? I've got debug logging turned on for org.springframework.ldap and org.apache.commons.pool2
Why is it seeming to take 15+minutes to determine that a connection is stale/unusable? How can I configure to make that much shorter?

score 1 · Answer 1 · answered Sep 20 '18 at 23:25

1

There is a good chance that the underlying LDAP system is having connection issues. You could try adding timeouts in the connection pool settings:

max-wait - default is -1
eviction-run-interval-millis - you may want to set this to control how often to check for problems

Docs: https://docs.spring.io/spring-ldap/docs/current/reference/#pool-configuration

answered Sep 20 '18 at 23:25

dbrin

15,525
4
56
83

That's the thing though. I don't want an error to return, I want it to decide that connection is no good faster, so it gives me one that IS good faster. max-wait will cause an error to be thrown, if the connection takes too long. eviction-run might be good, but I really want is a timeout for the connection test. – billjamesdev Sep 21 '18 at 02:01
My hope would be that once the connection is determined to be bad it will be thrown away. The testOnBorrow documentation says that another attempt will be made: "... If the object fails to validate, it will be dropped from the pool, and an attempt to borrow another will be made." – dbrin Sep 21 '18 at 03:54
Also, rereading your debug output I can see that it does retry the connection immediately at "2018-09-20 20:35:03.249". It's just that it didn't have a time set for how long to wait for the LDAP server to respond. I think it's worth a try setting max-wait. – dbrin Sep 21 '18 at 04:03
Unfortunately, this didn't work. max-wait is only used to determine how long the pool will BLOCK when no connections are available (all are borrowed). I found a connection timeout property here: https://stackoverflow.com/questions/23887669/implementation-of-timeout-in-ldap, that I'm trying now – billjamesdev Sep 21 '18 at 20:29

Pooled LdapTemplate stalls for minutes during context validation

1 Answers1