Working around issue of load balancer idle timeout to LDAP data connector

Sat Jul 6 05:17:52 UTC 2024

We're testing an IdP upgrade from 4.2 to 5.1. We noticed while
troubleshooting problem reports from SPs that we'd intermittently see our
LDAP connections fail unexpectedly during attribute resolution.

2024-07-01 15:21:36,430 -  - WARN
[org.ldaptive.transport.netty.NettyConnection:1750] - Inbound handler
caught exception for org.ldaptive.transport.netty.NettyConnection at 1775797583
::ldapUrl=[org.ldaptive.LdapURL at 533230943::scheme=ldaps, hostname=
ldap.example.edu, port=-1, baseDn=null, attributes=null, scope=null,
filter=null, inetAddress=null], isOpen=true,
connectTime=2024-07-02T01:18:56.876259946Z,
connectionConfig=[org.ldaptive.ConnectionConfig at 1017469636::ldapUrl=ldaps://
ldap.example.edu, connectTimeout=PT3S, startTLSTimeout=PT3S,
responseTimeout=PT3S, reconnectTimeout=PT10S, autoReconnect=true,
autoReconnectCondition=ONE_RECONNECT_ATTEMPT, autoReplay=false,
sslConfig=[org.ldaptive.ssl.SslConfig at 1138567678
::credentialConfig=[org.ldaptive.ssl.CredentialConfigFactory$2 at 2000791015::trustCertificates=suppressed,
authenticationCertificate=null, authenticationKey=null],
trustManagers=null, hostnameVerifier=null, enabledCipherSuites=null,
enabledProtocols=null, handshakeCompletedListeners=null,
handshakeTimeout=PT1M], useStartTLS=false,
connectionInitializers=[org.ldaptive.BindConnectionInitializer at 280593550::bindDn=cn=idp,
ou=Specials, dc=example, dc=edu, bindSaslConfig=null, bindControls=null],
connectionStrategy=[org.ldaptive.ActivePassiveConnectionStrategy at 1447385515
::ldapURLSet=[org.ldaptive.LdapURLSet at 1084246749
::active=[[org.ldaptive.LdapURL at 533230943::scheme=ldaps, hostname=
ldap.example.edu, port=-1, baseDn=null, attributes=null, scope=null,
filter=null, inetAddress=null]], inactive=[]],
activateCondition=DEFAULT_ACTIVATE_CONDITION,
retryCondition=DEFAULT_RETRY_CONDITION, initialized=true],
connectionValidator=null, transportOptions={}], channel=[id: 0x58764a9e, L:/
10.17.133.57:40824 - R:ldap.example.edu/10.10.10.10:636]
io.netty.channel.unix.Errors$NativeIoException: recvAddress(..) failed:
Connection reset by peer
2024-07-01 15:21:36,463 - 172.19.100.105 - WARN
[net.shibboleth.idp.attribute.resolver.impl.AttributeResolverImpl:396] -
Attribute Resolver 'ShibbolethAttributeResolver': Data connector 'UH_LDAP'
failed
net.shibboleth.idp.attribute.resolver.ResolutionException: Data Connector
'UH_LDAP': Unable to execute LDAP search
        at
net.shibboleth.idp.attribute.resolver.dc.ldap.impl.LDAPDataConnector.retrieveAttributes(LDAPDataConnector.java:214)
Caused by: org.ldaptive.LdapException: Connection closed
        at
org.ldaptive.transport.netty.NettyConnection.notifyOperationHandlesOfClose(NettyConnection.java:1119)
2024-07-01 15:21:36,464 - 172.19.100.105 - ERROR
[net.shibboleth.idp.profile.impl.ResolveAttributes:284] - Profile Action
ResolveAttributes: Error resolving attributes
net.shibboleth.idp.attribute.resolver.ResolutionException: Data Connector
'UH_LDAP': Unable to execute LDAP search
        at
net.shibboleth.idp.attribute.resolver.dc.ldap.impl.LDAPDataConnector.retrieveAttributes(LDAPDataConnector.java:214)
Caused by: org.ldaptive.LdapException: Connection closed
        at
org.ldaptive.transport.netty.NettyConnection.notifyOperationHandlesOfClose(NettyConnection.java:1119)

This results in inconsistent responses to the SP AuthnRequest such as the
following example from the connector failure above:

2024-07-01 15:21:36,494 - 172.19.100.105 - INFO [Shibboleth-Audit.SSO:333]
- 2024-07-01 15:21:36.494-1000|2024-07-01
15:21:06.197-1000|172.19.100.105|baron|https://foo.example.com|_91d72cf485f628798805b00e49dccfda|password|2024-07-01
15:21:36.419-1000||AAdzZWNyZXQxbqT3eUzq9oozK4s6pxqvwpCxnaSY0VCy29rELFL27s6PrOkibGM6bhYZdKXRuzRSrhio4rUAHQ5Py1/mCwzo3SSJ8myjmbmLDc+O+Oc+vxPtn17zxAnMtGhir1G7rtLZJi0=|transient|false|true||POST|POST||Success|||Mozilla/5.0
(Macintosh; Intel Mac OS X 10.15; rv:127.0) Gecko/20100101 Firefox/127.0

Compare with the expected result without the connector failure that allows
us to resolve attributes:

2024-07-01 15:22:02,625 - 172.19.100.105 - INFO [Shibboleth-Audit.SSO:333]
- 2024-07-01 15:22:02.625-1000|2024-07-01
15:21:45.647-1000|172.19.100.105|baron|https://foo.example.com|_df4dd6cbe39f37f5ce563a0a1e546e07|password|2024-07-01
15:22:02.504-1000|ATTR_1,ATTR_2|AAdzZWNyZXQxfJkq5fqz1IQALe6+cdE1a9020rWR+6w0W0nfNVwAaYH/2KU1cqNZKzhTTVEx47U6zPoP1RD1KwLQwQq3MrCOqspznzK5HQ3WyUpbGNTuv/rE0mCNjm5TAISTRdZEGPztf9E=|transient|false|true||POST|POST||Success|||Mozilla/5.0
(Macintosh; Intel Mac OS X 10.15; rv:127.0) Gecko/20100101 Firefox/127.0

When we fail to resolve the attributes, and return nothing to the SP with
no other indication of the error, the SP reacts accordingly to the lack of
expected attributes.

We ultimately determined that this appears to be because the load balancer
in front of our LDAP uses a 51 second idle timeout value for LDAP clients
as part of its direct server return feature. We hypothesize that the
clients utilize these LDAP pools, where they assume there are persistent
connections available, but they may not use them with a frequency less than
51s idle timeout. This results in situations where the clients try to use
the connections they assume are there, but the LB has already dropped the
connection because the idle timeout has been exceeded.

For now we appear to have mitigated this problem by setting the
validateTimerPeriod in our LDAP data connector definition in
attribute-resolver.xml to 30 seconds, a value well below the LB's idle
timeout value.

Has anyone else dealt with a similar issue? If so, how did you resolve it?
Are there other preferred/recommended ways to solve this problem?

Another approach we considered that ought to be reliable, would be if the
connection were validated before use. It seemed like maybe
validateOnCheckout might do this, but setting this to attribute to true in
the LDAP connector does not seem to have the desired effect. Both the IdP
and ldaptive documentation is ambiguous on exactly what Checkout and its
relationship to the use of the connection is.

Another viable option would be to have the IdP retry/reopen the closed LDAP
connection in this situation.

It appears the IdP supports (at least for LDAP Authn)
- LDAP.autoReconnect (default = true): "Whether lost connections should be
automatically reopened", but that doesn't seem to be happening here.

I also note that some of the LDAP connection parameters are logged,
including:
- retryCondition=DEFAULT_RETRY_CONDITION

But I don't see retryCondition in the set of IdP ldap property references
for either the IdP nor ldaptive, or what the default may be, or if this may
be in any way helpful to get it to retry in this situation.

Any feedback or suggestions would be welcome.

[*] LDAP connection pool references:
- <
https://shibboleth.atlassian.net/wiki/spaces/IDP5/pages/3199503942/ConnectionPool
>
- <https://www.ldaptive.org/docs/guide/connections/pooling.html>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20240705/d8bd93c9/attachment.htm>