LDAP authn connection pool locked up

[Chris Reeves]

Hi Daniel,

On Wed 14 Sep 2016 at 20:25:49 +0100, Daniel Fisher wrote:
> On Wed, Sep 14, 2016 at 2:05 PM, Chris Reeves wrote:
> >
> > 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.AbstractOperatio
> > n$ReopenOperationExceptionHandler:277] - Operation exception encountered,
> > reopening connection
> > 2016-09-13T08:37:30.402+01:00 - WARN [org.ldaptive.AbstractOperatio
> > n$ReopenOperationExceptionHandler:277] - Operation exception encountered,
> > reopening connection
> > 2016-09-13T08:37:30.402+01:00 - WARN [org.ldaptive.AbstractOperatio
> > n$ReopenOperationExceptionHandler:277] - Operation exception encountered,
> > reopening connection
> > --------
> 
> Were you able to confirm that the reopen was successful?

I can correlate most of the 'reopening connection' log messages with
successful binds and searches in our LDAP logs, so it looks like the reopen
was successful. The reopens appear to occur in groups of 3 (presumably because
our aggregateAuthenticator is searching three OUs).

  - The first set of reopens (~08:37:30) bind, search once and then do nothing
    more.
  - The second set of reopens (~08:37:39) bind and then do dozens of searches
    over the next 3 or 4 minutes.
  - The next set (~08:41:21) does a couple of searches before stopping. 
  - The next set (~08:41:29) bind and then do dozens of searches over the next
    6 minutes.
  - The final set (~08:41:58) bind and then do dozens of searches over the
    next 6 minutes.

> > 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
> > --------
> 
> These were probably the only two that the pool returned before the pool was
> emptied by the validator.
> And they likely were not in a working state either.

Possibly. The LDAP logs show that for the connections that are working they
are successfully searching for users. I can't see any attempts to bind as any
user (this is harder to spot though).

> > 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?
> 
> I'm guessing that the pool couldn't create new connections.
> Do you have any ldaptive logs that show what was happening to the pool?
> I'd be interested in the thread dump if you can share it off list.

No, I'm afraid not. There are no log messages from ldaptive other than those
similar to the ones above.

I'm happy to send you the thread-dump off-list, if that will be helpful.

> > 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?
> 
> Setting connectTimeout and responseTimeout on the connectionConfig may
> allow the connection pool to recover quicker.

If it recovers at all... There were obviously some successful reconnections,
but things still somehow got locked up.

Thanks for taking a look at this,
    Chris