LDAP authn connection pool locked up

[Jeffrey Crawford]

I've also struggled with the pooling config. Seems like I account for one
thing and the exact opposite happens next. I'm not sure it's an option for
you but ever since we've disabled pooling, we've had much higher stability.
There is probably some implication with having shibb do a handshake on each
LDAP connection, however it's not been an issue for us.

Most of the problems we've seen is when a network device will silently drop
a TCP connection, either due to some sort of idle timeout or if an LDAP
system suddenly crashes.

Jeffrey E. Crawford
Enterprise Service Team <jeffreyc at ucsc.edu>

Both pilots and IT professionals require training and currency before
charging into clouds!
---------------------------------------

On Thu, Sep 15, 2016 at 7:10 AM, Chris Reeves <chris.reeves at york.ac.uk>
wrote:

>
> 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
> --
> To unsubscribe from this list send an email to
> users-unsubscribe at shibboleth.net
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20160916/faaabc85/attachment.html>