LDAP authn connection pool locked up

[Chris Reeves]

Hi,

We experienced some issues yesterday morning with the service that provides
our LDAP authentication source. Routine patching of the F5 load balancer which
sits in front of our LDAP servers resulted in a couple of small blips in
network traffic to the LDAP service. Why this even happened is another
conversation (that I'm having elsewhere), but what I'd like to understand here
is the impact that this had upon our Shibboleth service.


The first sign that we saw of issues with LDAP authentication were the
following messages suggesting that the IdP was reconnecting:
--------
2016-09-13T08:37:30.401+01:00 - WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler:277] - Operation exception encountered, reopening connection
2016-09-13T08:37:30.402+01:00 - WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler:277] - Operation exception encountered, reopening connection
2016-09-13T08:37:30.402+01:00 - WARN [org.ldaptive.AbstractOperation$ReopenOperationExceptionHandler:277] - Operation exception encountered, reopening connection
--------

Following these initial messages we only saw two authentication attempts
complete:
--------
2016-09-13T08:37:48.076+01:00 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:152] - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by 'user1' failed
2016-09-13T08:39:05.566+01:00 - INFO [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:152] - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by 'user2' failed
--------

We could see AuthnRequests arriving, but no further log activity. Occasionally
we saw errors similar to the following:
--------
2016-09-13T08:39:04.566+01:00 - ERROR [org.springframework.webflow.conversation.impl.LockTimeoutException:76] -
org.springframework.webflow.conversation.impl.LockTimeoutException: Unable to acquire conversation lock after 30 seconds
        at org.springframework.webflow.conversation.impl.JdkConcurrentConversationLock.lock(JdkConcurrentConversationLock.java:44)
--------

A little Googling turned up a thread from September 2015[1] which discussed
this error message. Scott's look at the SWF code suggested that this "is
likely the result of users getting tired of waiting and reloading pages,
causing requests for a given conversation to back up waiting on the hung
request." So based on that thread I'm thinking that the authentication
requests arrived, the IdP presented the user with the login page, the user
submitted their credentials and then the web flow moved to the next step where
it attempts to validate those credentials. At this point things got stuck due
to issues with the LDAP connection pool (e.g. no non-broken connections).

The flow getting stuck resulted in some users resubmitting their credentials
and triggering the 'conversation lock' error above as the flow was already
locked trying to verify the previous set of credentials. The other, more
serious, effect of the locked flow is that it used up one of the 200
connection threads available to Tomcat. The IdP continued responding to
requests for its status page until 08:47:28, at which point the last of the
200 available threads became stuck.

A thread dump of the Java process lists 199 threads waiting on a lock (called
for by org.ldaptive.pool.BlockingConnectionPool):
--------
"ajp-nio-8009-exec-263" #53432 daemon prio=5 os_prio=0 tid=0x00007fd178e6c000 nid=0x58bf waiting on condition [0x00007fd14cf7b000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d9c48818> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:111)
        at org.ldaptive.pool.PooledConnectionFactory.getConnection(PooledConnectionFactory.java:82)
        at org.ldaptive.auth.PooledBindAuthenticationHandler.getConnection(PooledBindAuthenticationHandler.java:78)
        at org.ldaptive.auth.AbstractAuthenticationHandler.authenticate(AbstractAuthenticationHandler.java:70)
        at org.ldaptive.auth.AggregateDnResolver$AuthenticationHandler.authenticate(AggregateDnResolver.java:285)
        at org.ldaptive.auth.Authenticator.authenticate(Authenticator.java:250)
        at org.ldaptive.auth.Authenticator.authenticate(Authenticator.java:215)
        at net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP.doExecute(ValidateUsernamePasswordAgainstLDAP.java:136)
--------
Curiously, I can't find any thread with ID 0x00000000d9c48818 listed, although
I could be misinterpreting the thread dump.


We're running IdP 3.2.1 with all of the basic connection pool configuration in
ldap-authn-config.xml left at their defaults. Our only customisation (outside
of basic properties) is the use of an aggregateAuthenticator, which uses the
existing bindSearchPooledConnectionFactory.

Any ideas why the LDAP connection pool got locked up? It seems to have been
detecting broken connections to a certain extent, as we see connections being
reopened in the logs (although there are only 20 log entries to this effect,
spread between 08:37:30 and 08:52:37). I would have thought it should be able
to recover from a blip in connectivity to its LDAP authentication source - the
blip would have been less than a second, but even if it had been as long as 10
seconds that should have been recoverable, surely?

Are there any config options that we should be looking at tweaking, such as
timeouts, retry counts, validation, etc. that could improve the situation if
this were to happen again?


Many thanks in advance,
    Chris

[1] https://shibboleth.net/pipermail/users/2015-September/024311.html