IdP 3 strange startup delay

Youssef GHORBAL youssef.ghorbal at pasteur.fr
Wed Mar 30 19:49:59 EDT 2016


Hello,

	I’m facing a strange stratup delay on an IdP 3.2.1 runnning on a CentOS 7 (OpenJDK 8) inside a jetty-9.3.8.v20160314.
	The startup process stops for ~40 seconds at "Parsing configuration for attribute filter policy: DefaultPasteurAttributes”
	Here’s the log section :

[…]
2016-03-31 01:26:41,023 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:172] - Service 'shibboleth.AttributeFilterService': Performing initial load
2016-03-31 01:26:41,023 - INFO [net.shibboleth.utilities.java.support.service.AbstractReloadableService:258] - Service 'shibboleth.AttributeFilterService': Reloading service configuration
2016-03-31 01:26:41,028 - INFO [net.shibboleth.ext.spring.util.SchemaTypeAwareXMLBeanDefinitionReader:317] - Loading XML bean definitions from file [/opt/shibboleth-idp/conf/attribute-filter.xml]
2016-03-31 01:26:41,061 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeFilterPolicyGroupParser:66] - Parsing attribute filter policy group ShibbolethFilterPolicy
2016-03-31 01:26:41,063 - DEBUG [net.shibboleth.idp.attribute.filter.spring.BaseFilterParser:169] - Element 'AttributeFilterPolicy' 'id' attribute 'DefaultPasteurAttributes' is mapped to '/AttributeFilterPolicyGroup:ShibbolethFilterPolicy/AttributeFilterPolicy:DefaultPasteurAttributes'
2016-03-31 01:26:41,064 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeFilterPolicyParser:84] - Parsing configuration for attribute filter policy: DefaultPasteurAttributes
2016-03-31 01:27:29,983 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2016-03-31 01:27:29,985 - DEBUG [net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97] - permitValueRules [Generic bean: class [net.shibboleth.idp.attribute.filter.Matcher$1]; scope=prototype; abstract=false; lazyInit=false; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
[…]

	As you can see there is a gap of ~40s between “[net.shibboleth.idp.attribute.filter.spring.impl.AttributeFilterPolicyParser:84]” and "[net.shibboleth.idp.attribute.filter.spring.impl.AttributeRuleParser:97]”

	This behaviour is systematic and the “pause” time ranges from ~30s to ~60s

	I’m already @DEBUG log level, how can I dig further ? What can make it take so long at that step ?
	
	I’ll test with an “empty” attribute-filter.xml file and comment further.

Youssef


More information about the users mailing list