Handling empty LDAP connection pools on IdP start-up

Thu Mar 9 12:50:16 EST 2017

It definitely doesn’t start. In fact, status.sh can’t connect to the servlet; it’s quite dead.

Here’s logs from start-up yesterday morning.

Keith

2017-03-08 06:11:47,102 - ERROR [org.ldaptive.pool.BlockingConnectionPool:509] [session=] [ip=] - [org.ldaptive.pool.BlockingConnectionPool at 559037979::name=resolver-pool, poolConfig=[org.ldaptive.pool.PoolConfig at 1684129395::minPoolSize=0, maxPoolSize=20, validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=600, validateTimeout=5000], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator at 504485692::searchRequest=[org.ldaptive.SearchRequest at 1096824213::baseDn=<removed> 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]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy at 1321697288::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFactory=[org.ldaptive.DefaultConnectionFactory at 180820951::provider=org.ldaptive.provider.jndi.JndiProvider at 64e6cdad, config=[org.ldaptive.ConnectionConfig at 827511881::ldapUrl=ldap://ldap-test.cites.illinois.edu, connectTimeout=3000, responseTimeout=3000, sslConfig=[org.ldaptive.ssl.SslConfig at 798346769::credentialConfig=org.ldaptive.ssl.CredentialConfigFactory$2 at 2f349170, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=true, connectionInitializer=[org.ldaptive.BindConnectionInitializer at 367803404::bindDn=<removed>, bindSaslConfig=null, bindControls=null]]], initialized=true, availableCount=0, activeCount=0] unable to connect to the ldap
org.ldaptive.provider.ConnectionException: javax.naming.CommunicationException: ldap-test.cites.illinois.edu:389 [Root exception is java.net.ConnectException: Connection refused (Connection refused)]
	at org.ldaptive.provider.jndi.JndiStartTLSConnectionFactory.createInternal(JndiStartTLSConnectionFactory.java:95)
Caused by: javax.naming.CommunicationException: ldap-test.cites.illinois.edu:389
	at com.sun.jndi.ldap.Connection.<init>(Connection.java:216)
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.net.PlainSocketImpl.socketConnect(Native Method)
2017-03-08 06:11:47,111 - WARN [org.ldaptive.pool.BlockingConnectionPool:600] [session=] [ip=] - unable to create active connection
2017-03-08 06:11:47,111 - ERROR [org.ldaptive.pool.BlockingConnectionPool:197] [session=] [ip=] - Could not service check out request
2017-03-08 06:11:47,113 - ERROR [net.shibboleth.idp.attribute.resolver.dc.ldap.impl.ConnectionFactoryValidator:152] [session=] [ip=] - Connection factory validation failed
org.ldaptive.pool.PoolExhaustedException: Pool is empty and connection creation failed
	at org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:198)
2017-03-08 06:11:47,115 - ERROR [net.shibboleth.idp.attribute.resolver.dc.ldap.impl.LDAPDataConnector:145] [session=] [ip=] - Data Connector 'myLDAP': Invalid connector configuration
net.shibboleth.idp.attribute.resolver.dc.ValidationException: [org.ldaptive.pool.PoolExhaustedException at 1584080449::resultCode=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=Pool is empty and connection creation failed, providerException=null]
	at net.shibboleth.idp.attribute.resolver.dc.ldap.impl.ConnectionFactoryValidator.validate(ConnectionFactoryValidator.java:154)
Caused by: org.ldaptive.pool.PoolExhaustedException: Pool is empty and connection creation failed
	at org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:198)
2017-03-08 06:11:47,152 - WARN [net.shibboleth.ext.spring.context.FilesystemGenericApplicationContext:549] [session=] [ip=] - Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'myLDAP': Invocation of init method failed; nested exception is net.shibboleth.utilities.java.support.component.ComponentInitializationException: Data Connector 'myLDAP': Invalid connector configuration
2017-03-08 06:11:47,168 - ERROR [net.shibboleth.utilities.java.support.service.AbstractReloadableService:181] [session=] [ip=] - Service 'shibboleth.AttributeResolverService': Initial load failed
net.shibboleth.utilities.java.support.service.ServiceException: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'myLDAP': Invocation of init method failed; nested exception is net.shibboleth.utilities.java.support.component.ComponentInitializationException: Data Connector 'myLDAP': Invalid connector configuration
	at net.shibboleth.ext.spring.service.ReloadableSpringService.doReload(ReloadableSpringService.java:336)
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'myLDAP': Invocation of init method failed; nested exception is net.shibboleth.utilities.java.support.component.ComponentInitializationException: Data Connector 'myLDAP': Invalid connector configuration
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1578)
Caused by: net.shibboleth.utilities.java.support.component.ComponentInitializationException: Data Connector 'myLDAP': Invalid connector configuration
	at net.shibboleth.idp.attribute.resolver.dc.ldap.impl.LDAPDataConnector.doInitialize(LDAPDataConnector.java:146)
Caused by: net.shibboleth.idp.attribute.resolver.dc.ValidationException: [org.ldaptive.pool.PoolExhaustedException at 1584080449::resultCode=null, matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, message=Pool is empty and connection creation failed, providerException=null]
	at net.shibboleth.idp.attribute.resolver.dc.ldap.impl.ConnectionFactoryValidator.validate(ConnectionFactoryValidator.java:154)
Caused by: org.ldaptive.pool.PoolExhaustedException: Pool is empty and connection creation failed
	at org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:198)

A little later:
2017-03-08 06:11:48,050 - ERROR [net.shibboleth.idp.saml.metadata.impl.AttributeMappingNodeProcessor:144] [session=] [ip=] - Requested Attributes Mapper: Invalid Attribute resolver configuration.
2017-03-08 06:11:48,055 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:465] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver itrustDev: New metadata successfully loaded for 'http://itrust-dev.cites.illinois.edu/itrust-metadata/itrust-metadata.xml'
2017-03-08 06:11:48,055 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:306] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver itrustDev: Next refresh cycle for metadata provider 'http://itrust-dev.cites.illinois.edu/itrust-metadata/itrust-metadata.xml' will occur on '2017-03-08T12:11:53.055Z' ('2017-03-08T06:11:53.055-06:00' local time)
2017-03-08 06:11:48,087 - ERROR [net.shibboleth.idp.saml.metadata.impl.AttributeMappingNodeProcessor:144] [session=] [ip=] - Requested Attributes Mapper: Invalid Attribute resolver configuration.
2017-03-08 06:11:48,089 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:465] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver itrustTest: New metadata successfully loaded for 'https://discovery-test.itrust.illinois.edu/itrust-metadata/itrust-metadata.xml'
2017-03-08 06:11:48,089 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:306] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver itrustTest: Next refresh cycle for metadata provider 'https://discovery-test.itrust.illinois.edu/itrust-metadata/itrust-metadata.xml' will occur on '2017-03-08T12:11:53.089Z' ('2017-03-08T06:11:53.089-06:00' local time)
2017-03-08 06:11:48,444 - ERROR [net.shibboleth.idp.saml.metadata.impl.AttributeMappingNodeProcessor:144] [session=] [ip=] - Requested Attributes Mapper: Invalid Attribute resolver configuration.
2017-03-08 06:11:48,497 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:465] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver itrust: New metadata successfully loaded for 'https://discovery.itrust.illinois.edu/itrust-metadata/itrust-metadata.xml'
2017-03-08 06:11:48,497 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:306] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver itrust: Next refresh cycle for metadata provider 'https://discovery.itrust.illinois.edu/itrust-metadata/itrust-metadata.xml' will occur on '2017-03-08T12:11:53.497Z' ('2017-03-08T06:11:53.497-06:00' local time)
2017-03-08 06:11:48,502 - ERROR [net.shibboleth.idp.saml.metadata.impl.AttributeMappingNodeProcessor:144] [session=] [ip=] - Requested Attributes Mapper: Invalid Attribute resolver configuration.
2017-03-08 06:11:48,503 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:465] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver aws: New metadata successfully loaded for 'https://signin.aws.amazon.com/static/saml-metadata.xml'
2017-03-08 06:11:48,503 - INFO [org.opensaml.saml.metadata.resolver.impl.AbstractReloadingMetadataResolver:306] [session=] [ip=] - Metadata Resolver FileBackedHTTPMetadataResolver aws: Next refresh cycle for metadata provider 'https://signin.aws.amazon.com/static/saml-metadata.xml' will occur on '2017-03-08T12:11:53.503Z' ('2017-03-08T06:11:53.503-06:00' local time)
2017-03-08 06:11:48,546 - ERROR [net.shibboleth.idp.saml.metadata.impl.AttributeMappingNodeProcessor:144] [session=] [ip=] - Requested Attributes Mapper: Invalid Attribute resolver configuration.

And a little after that:
2017-03-08 06:11:48,816 - WARN [net.shibboleth.ext.spring.context.DelimiterAwareApplicationContext:549] [session=] [ip=] - Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'shibboleth.metrics.RegisterMetricSets$child#0' defined in file [/services/shib-idp/opt/idp/system/conf/../../conf/admin/metrics.xml]: Cannot resolve reference to bean 'shibboleth.metrics.AttributeResolverGaugeSet' while setting bean property 'arguments' with key [7]; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'shibboleth.metrics.AttributeResolverGaugeSet' defined in file [/services/shib-idp/opt/idp/system/conf/general-admin-system.xml]: Invocation of init method failed; nested exception is net.shibboleth.utilities.java.support.component.ComponentInitializationException: Injected service was null or not an AttributeResolver
2017-03-08 06:11:48,817 - INFO [net.shibboleth.ext.spring.context.DelimiterAwareApplicationContext:982] [session=] [ip=] - Closing Root WebApplicationContext: startup date [Wed Mar 08 06:11:27 CST 2017]; root of context hierarchy
2017-03-08 06:11:48,818 - WARN [net.shibboleth.ext.spring.context.DelimiterAwareApplicationContext:1000] [session=] [ip=] - Exception thrown from LifecycleProcessor on context close
java.lang.IllegalStateException: LifecycleProcessor not initialized - call 'refresh' before invoking lifecycle methods via the context: Root WebApplicationContext: startup date [Wed Mar 08 06:11:27 CST 2017]; root of context hierarchy
	at org.springframework.context.support.AbstractApplicationContext.getLifecycleProcessor(AbstractApplicationContext.java:416)

Finally:
2017-03-08 06:11:48,855 - ERROR [org.springframework.web.context.ContextLoader:351] [session=] [ip=] - Context initialization failed
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'shibboleth.metrics.RegisterMetricSets$child#0' defined in file [/services/shib-idp/opt/idp/system/conf/../../conf/admin/metrics.xml]: Cannot resolve reference to bean 'shibboleth.metrics.AttributeResolverGaugeSet' while setting bean property 'arguments' with key [7]; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'shibboleth.metrics.AttributeResolverGaugeSet' defined in file [/services/shib-idp/opt/idp/system/conf/general-admin-system.xml]: Invocation of init method failed; nested exception is net.shibboleth.utilities.java.support.component.ComponentInitializationException: Injected service was null or not an AttributeResolver
	at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:359)
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'shibboleth.metrics.AttributeResolverGaugeSet' defined in file [/services/shib-idp/opt/idp/system/conf/general-admin-system.xml]: Invocation of init method failed; nested exception is net.shibboleth.utilities.java.support.component.ComponentInitializationException: Injected service was null or not an AttributeResolver
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1578)
Caused by: net.shibboleth.utilities.java.support.component.ComponentInitializationException: Injected service was null or not an AttributeResolver
	at net.shibboleth.idp.attribute.resolver.impl.AttributeResolverServiceGaugeSet.doInitialize(AttributeResolverServiceGaugeSet.java:104)

From: users [mailto:users-bounces at shibboleth.net] On Behalf Of Daniel Fisher
Sent: Thursday, March 09, 2017 10:45 AM
To: Shib Users <users at shibboleth.net>
Subject: Re: Handling empty LDAP connection pools on IdP start-up

On Thu, Mar 9, 2017 at 11:02 AM, Wessel, Keith <kwessel at illinois.edu> wrote:
All,

We recently added connection pooling to our LDAP data connectors to speed thing sup. I was hoping, based on past experience with database connection pooling, to allow the IdP to go about its business if it started up and couldn't create any connections in the pool. That is, if the LDAP server was unavailable, it would go ahead and start and keep trying to create LDAP connections. This shouldn't happen since our LDAP server is clustered, but I'm all for making things as fault-proof as possible.

Yesterday morning, our test LDAP cluster was down when our test IdP nodes restarted, and they all reported not being able to initialize the LDAP connection pool.

I have this in my LDAP data connectors:
        <ConnectionPool maxPoolSize="20" blockWaitTime="PT5S"
            expirationTime="PT10M" failFastInitialize="false"
            validatePeriodically="true" validateTimerPeriod="PT10M"
            validateDN="%{idp.attribute.resolver.LDAP.bindDN" />

I left out the min pool size with the impression that it defaults to 0. I also didn't' see any params discussing an initial pool size, assuming that it was the ame as the min pool size.

Correct, it defaults to 0.

Am I overlooking something? How do I get the pool to initialize even if it can't create connections?

 The failFastInitialize attribute is the key piece and you've correctly set it to false for the behavior you want. The IDP should successfully start even though the connection pool is empty. Can you share some logs from this event?

--Daniel Fisher