[JIRA] Created: (SC-178) IdP fails to start when AttributeFilterEngine uses FileBackedHttpResource and the remote resource is unavailable, but a (usable) backup file is present

Kaspar Brand (JIRA) noreply at shibboleth.net
Tue Apr 17 13:02:03 BST 2012 

IdP fails to start when AttributeFilterEngine uses FileBackedHttpResource and the remote resource is unavailable, but a (usable) backup file is present
-------------------------------------------------------------------------------------------------------------------------------------------------------

                 Key: SC-178
                 URL: https://issues.shibboleth.net/jira/browse/SC-178
             Project: Shibboleth Common - Java
          Issue Type: Bug
          Components: Configuration
    Affects Versions: 1.3.5
            Reporter: Kaspar Brand
            Assignee: Chad La Joie


When used for a ConfigurationResource within the AttributeFilterEngine service, the FileBackedHttpResource doesn't seem to work when the IdP starts up - or at least not in the way I would expect it to (https://wiki.shibboleth.net/confluence/display/SHIB2/IdPConfigResource#IdPConfigResource-FilebackedHTTPResource says: "The backup copy is used if the remote copy cannot be reached (assuming an initial copy was successfully fetched)").

When configuring a FilesystemResource for the AttributeFilterEngine like this -

    <srv:Service id="shibboleth.AttributeFilterEngine" xsi:type="attribute-afp:ShibbolethAttributeFilteringEngine">
        <srv:ConfigurationResource xsi:type="resource:FilesystemResource" file="/opt/shibboleth-idp/conf/attribute-filter.xml"/>
    </srv:Service>

... and putting a valid config under /opt/shibboleth-idp/conf/attribute-filter.xml, everything is fine with the IdP:

2012-04-17 13:29:28,013 - DEBUG [edu.internet2.middleware.shibboleth.common.config.BaseReloadableService:136] - Initializing shibboleth.AttributeFilterEngine service with resources: [/opt/shibboleth-idp/conf/attribute-filter.xml]
2012-04-17 13:29:28,014 - INFO [edu.internet2.middleware.shibboleth.common.config.BaseService:158] - Loading new configuration for service shibboleth.AttributeFilterEngine
[...]
2012-04-17 13:29:38,791 - INFO [edu.internet2.middleware.shibboleth.common.config.BaseService:180] - shibboleth.AttributeFilterEngine service loaded new configuration


Changing to a FileBackedHttpResource, however, makes the startup fail - even if /opt/shibboleth-idp/conf/attribute-filter.xml is still present on the local file system (and has the same contents as before). I.e., changing the snippet in service.xml to

    <srv:Service id="shibboleth.AttributeFilterEngine" xsi:type="attribute-afp:ShibbolethAttributeFilteringEngine"
        configurationResourcePollingFrequency="PT1H" configurationResourcePollingRetryAttempts="128">
        <srv:ConfigurationResource xsi:type="resource:FileBackedHttpResource"
            url="https://www.example.org/my/attribute-filter.xml" file="/opt/shibboleth-idp/conf/attribute-filter.xml"/>
    </srv:Service>

will only produce this single line in idp-process.log:

2012-04-17 13:32:20,142 - DEBUG [edu.internet2.middleware.shibboleth.common.config.BaseReloadableService:136] - Initializing shibboleth.AttributeFilterEngine service with resources: [https://www.example.org/my/attribute-filter.xml]

after which the IdP cancels the startup. In the container log (and only there) we then see:

Apr 17, 2012 1:32:20 PM org.apache.catalina.core.StandardContext listenerStart
SEVERE: Exception sending context initialized event to listener instance of class org.springframework.web.context.ContextLoaderListener
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'shibboleth.AttributeFilterEngine': Invocation of init method failed; nested exception is edu.internet2.middleware.
shibboleth.common.service.ServiceException: Unable to initialize service: shibboleth.AttributeFilterEngine
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1338)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:473)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380)
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185)
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429)
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728)
        at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380)
        at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:255)
        at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:199)
        at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:45)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3972)
        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4467)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:526)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:637)
        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:563)
        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498)
        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)
        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321)
        at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)
        at org.apache.catalina.core.StandardHost.start(StandardHost.java:722)
        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)
        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443)
        at org.apache.catalina.core.StandardService.start(StandardService.java:516)
        at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:593)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)
Caused by: edu.internet2.middleware.shibboleth.common.service.ServiceException: Unable to initialize service: shibboleth.AttributeFilterEngine
        at edu.internet2.middleware.shibboleth.common.config.BaseReloadableService.initialize(BaseReloadableService.java:150)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1414)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1375)
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1335)
        ... 39 more
Caused by: org.opensaml.util.resource.ResourceException: Unable to contact resource URL: https://www.example.org/my/attribute-filter.xml
        at org.opensaml.util.resource.HttpResource.exists(HttpResource.java:94)
        at org.opensaml.util.resource.FileBackedHttpResource.exists(FileBackedHttpResource.java:120)
        at org.opensaml.util.resource.ResourceChangeWatcher.<init>(ResourceChangeWatcher.java:114)
        at edu.internet2.middleware.shibboleth.common.config.BaseReloadableService.initialize(BaseReloadableService.java:141)
        ... 46 more
Caused by: java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:327)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:193)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:180)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:384)
        at java.net.Socket.connect(Socket.java:546)
        at sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:584)
        at sun.security.ssl.SSLSocketImpl.<init>(SSLSocketImpl.java:426)
        at sun.security.ssl.SSLSocketFactoryImpl.createSocket(SSLSocketFactoryImpl.java:142)
        at org.apache.commons.httpclient.protocol.SSLProtocolSocketFactory.createSocket(SSLProtocolSocketFactory.java:82)
        at org.apache.commons.httpclient.protocol.SSLProtocolSocketFactory.createSocket(SSLProtocolSocketFactory.java:127)
        at org.apache.commons.httpclient.HttpConnection.open(HttpConnection.java:707)
        at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:387)
        at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
        at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
        at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
        at org.opensaml.util.resource.HttpResource.exists(HttpResource.java:87)
        ... 49 more
Apr 17, 2012 1:32:20 PM org.apache.catalina.core.ApplicationContext log
INFO: Closing Spring root WebApplicationContext


In my understanding, the BaseReloadableService should try to fall back to the backup copy (and the IdP continue with the startup, therefore). And second, can the logging in case of AttributeFilterEngine startup errors be improved, so that it is also seen in idp-process.log?

--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira

More information about the commits mailing list