Sjibb LDAP pool hangs on firewall TCP session truncation

[Rich Graves]

Daniel Fisher wrote: 
> I'm still curious why your connections are getting dropped if searches are occurring every 5 minutes. 

Me too, doesn't make sense. AFAICT my test and production instances are identical except for more CPU/RAM available to the latter, and so far I am unable to reproduce in test.

> Edit the ldap-authn-config.xml file and add the following configuration to the connectionConfig bean: 
> p:responseTimeout="%{idp.authn.LDAP.responseTimeout:3000}" 

Progress, thanks! Although I haven't been able to reproduce the blocking production failure in test (production was fixed by increasing firewall idle timeouts), when I (intentionally) break the test system's access to LDAP by dropping responses with client-side iptables, what I see is:
  a) a quick responseTimeout
  b) the pooled connection validator kills the connection
  c) an exception is raised and caught
  d) the user is sent back to the login form with visible error "Login Failure: Validation of connection failed."
Ideally, I would like to see the shibb server automatically retry with the next LDAP server in the list instead of (d). Can that be done? Anyway, the responseTimeout behavior is much better than a long uncaught timeout.

Another related observation: the user or users need to fail and see the "Validation of connection failed" error idp.pool.LDAP.minSize times, not just once. Why? Because at least on my system, all idp.pool.LDAP.minSize..maxSize connections are created with the first working member of the idp.authn.LDAP.ldapURL list. Can I tell ldaptive to use ldapUrl in series or at random instead of as an ordered failover list? True, LDAP server failures should be very rare events.

2016-06-14 10:55:08,280 - DEBUG [org.ldaptive.SearchOperation:138] - execute request=[org.ldaptive.SearchRequest at -1423682449::baseDn=, searchFilter=[org.ldaptive.SearchFilter at 1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, followReferrals=false, intermediateResponseHandlers=null] with connection=[org.ldaptive.DefaultConnectionFactory$DefaultConnection at 1161719396::config=[org.ldaptive.ConnectionConfig at 1145746785::ldapUrl=ldaps://dc04.ads.carleton.edu:636 ldaps://dc00.ads.carleton.edu:636 ldaps://dc01.ads.carleton.edu:636 ldaps://dc02.ads.carleton.edu:636 ldaps://dc03.ads.carleton.edu:636, connectTimeout=2000, responseTimeout=2000, sslConfig=[org.ldaptive.ssl.SslConfig at 942398406::credentialConfig=net.shibboleth.idp.authn.impl.X509ResourceCredentialConfig at 3a221cc8, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=true, useStartTLS=false, connectionInitializer=null], providerConnectionFactory=[org.ldaptive.provider.jndi.JndiConnectionFactory at 1318390974::metadata=[ldapUrl=ldaps://dc04.ads.carleton.edu:636 ldaps://dc00.ads.carleton.edu:636 ldaps://dc01.ads.carleton.edu:636 ldaps://dc02.ads.carleton.edu:636 ldaps://dc03.ads.carleton.edu:636, count=1], environment={java.naming.ldap.factory.socket=org.ldaptive.ssl.ThreadLocalTLSSocketFactory, com.sun.jndi.ldap.connect.timeout=2000, java.naming.ldap.version=3, java.naming.factory.initial=com.sun.jndi.ldap.LdapCtxFactory, java.naming.security.protocol=ssl, com.sun.jndi.ldap.read.timeout=2000}, providerConfig=[org.ldaptive.provider.jndi.JndiProviderConfig at 251314831::operationExceptionResultCodes=[PROTOCOL_ERROR, SERVER_DOWN], properties={}, connectionStrategy=org.ldaptive.provider.ConnectionStrategies$DefaultConnectionStrategy at 47cf8fed, controlProcessor=org.ldaptive.provider.ControlProcessor at e0552c7, environment=null, tracePackets=null, removeDnUrls=true, searchIgnoreResultCodes=[TIME_LIMIT_EXCEEDED, SIZE_LIMIT_EXCEEDED, PARTIAL_RESULTS], sslSocketFactory=null, hostnameVerifier=null]], providerConnection=org.ldaptive.provider.jndi.JndiConnection at 68934f45]
2016-06-14 10:55:10,282 - DEBUG [org.ldaptive.provider.jndi.NamingExceptionUtils:358] - naming exception class javax.naming.NamingException is ambiguous, maps to multiple result codes: [OPERATIONS_ERROR, ALIAS_PROBLEM, ALIAS_DEREFERENCING_PROBLEM, LOOP_DETECT, AFFECTS_MULTIPLE_DSAS, OTHER]
2016-06-14 10:55:10,282 - DEBUG [org.ldaptive.provider.jndi.NamingExceptionUtils:396] - could not find result code in naming exception LDAP response read timed out, timeout used:2000ms.
2016-06-14 10:55:10,284 - DEBUG [org.ldaptive.pool.SearchValidator:100] - validation failed for search request [org.ldaptive.SearchRequest at -1423682449::baseDn=, searchFilter=[org.ldaptive.SearchFilter at 1642584434::filter=(objectClass=*), parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, searchEntryHandlers=null, searchReferenceHandlers=null, controls=null, followReferrals=false, intermediateResponseHandlers=null]
org.ldaptive.LdapException: javax.naming.NamingException: LDAP response read timed out, timeout used:2000ms.; remaining name ''
        at org.ldaptive.provider.ProviderUtils.throwOperationException(ProviderUtils.java:77)
Caused by: javax.naming.NamingException: LDAP response read timed out, timeout used:2000ms.
        at com.sun.jndi.ldap.Connection.readReply(Connection.java:490)
2016-06-14 10:55:10,284 - WARN [org.ldaptive.pool.BlockingConnectionPool:683] - connection failed check out validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 453f4c6b
2016-06-14 10:55:10,285 - DEBUG [org.ldaptive.pool.BlockingConnectionPool:645] - attempt to remove unknown available connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 453f4c6b
2016-06-14 10:55:10,288 - INFO [org.ldaptive.pool.BlockingConnectionPool:657] - destroyed connection: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 453f4c6b
2016-06-14 10:55:10,288 - WARN [net.shibboleth.idp.authn.impl.ValidateUsernamePasswordAgainstLDAP:175] - Profile Action ValidateUsernamePasswordAgainstLDAP: Login by rgraves produced exception
org.ldaptive.pool.ValidationException: Validation of connection failed
        at org.ldaptive.pool.AbstractConnectionPool.activateAndValidateConnection(AbstractConnectionPool.java:685)