Hi Adam, Thanks for the details. You found a bug, FELIX-4171 . I've committed a fix and am thinking about how to write a test.
In the scenario I thought of, I think your failing component has at least 2 dependencies and the WindowsLogger is not the last one. When the failing component is first enabled the WindowsLogger is present but by the time the failing component is attempted to be activated it isn't. The component manager then tries to close all the dependency managers, but the one(s) that haven't been opened cause the NPE you see. It is possible for the activation attempt to have a race condition with unregistering the dependency (WindowsLogger) so the failure to activate is always going to be a possibility. However I think it's more likely that you ran into the defect I fixed recently FELIX-4166 where for a delayed component removing a required dependency before the component is activated did not make it unsatisfied. So probably upgrading to yesterdays trunk would have fixed the problem, but better to get current trunk with the fix for the issue you found. If my guesses are accurate enough and you have enough logging turned on you should be able to see the WindowsLogger get deactivated before your failing component is activated. If this is not what is going on please let me know some more details! thanks david jencks On Jul 17, 2013, at 2:11 PM, Adam Purkiss <[email protected]> wrote: > Sorry let me explain a little better. DependencyManager in this case is SCR > related. It was noted during startup that we see a failure to bind reference > message and the stack trace has Caused by: java.lang.NullPointerException at > org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1746) > What puzzled me at first is why during startup there would be a call to > unbind and where the NPE is coming from. The windows logger component is not > much during activate or any of its set calls that I can see. > We have been running the trunk build as of end of May and this seems to be an > intermittent issue that is not easy to reproduce. When I did an update and > tried to build it I noticed that it took three attempts before it would build > so I am not sure if there are real test issues or if the tests themselves > have issues. We can try to update to the last few changes made in July. If > you have some thoughts on what could be up that would be good though. > >> Subject: Re: NPE from DependencyManager in scr code >> From: [email protected] >> Date: Wed, 17 Jul 2013 11:47:13 -0700 >> To: [email protected] >> >> I'm not clear on what you are describing. There's a DependencyManager class >> in SCR and also a felix component called DependencyManager. Also is this >> problem in your code or while trying to build a felix component? >> >> If the problem is in SCR/DS could you try again with current trunk? >> Possibly the problem already got fixed. >> >> thanks >> david jencks >> >> On Jul 17, 2013, at 11:39 AM, Adam Purkiss <[email protected]> wrote: >> >>> We are noticing an intermittent issue with DependencyManager (build of 1.7 >>> snapshot with all changes up to and including May 29). Not sure what is >>> causing this behaviour. Does anyone have thoughts on what it might be? Are >>> we doing something wrong or is it a threading issue we are running into? I >>> tried to get the latest code built but I was finding that "mvn clean >>> install" failed 2 out of 4 times, one with a test failure and one with a >>> different error to do with fail safe so I am not sure how safe the latest >>> code changes are. I don't understand why at this point it is trying to do >>> an unbind as the system is starting up. >>> thanks >>> >>> >>> 2013.07.17 12:22:50.759 [ERROR]: >>> [com.nuance.docimg.dws.core.logprovider.impl.LogServiceImpl(15)] Cannot >>> create >>> component instance due to failure to bind reference WindowsLogger >>> >>> 2013.07.17 12:22:50.759 [ERROR]: FrameworkEvent ERROR >>> >>> org.apache.felix.log.LogException: >>> org.osgi.framework.ServiceException: Service factory exception: null >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:312) >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:219) >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:320) >>> >>> >>> at org.apache.felix.framework.Felix.getService(Felix.java:3568) >>> >>> >>> at >>> org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:468) >>> >>> >>> at >>> org.apache.felix.scr.impl.helper.BindMethod.getServiceObject(BindMethod.java:572) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2072) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.prebind(DependencyManager.java:836) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1406) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1034) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ImmediateComponentManager.getServiceInternal(ImmediateComponentManager.java:736) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ImmediateComponentManager.getService(ImmediateComponentManager.java:706) >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:308) >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:219) >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:320) >>> >>> >>> at org.apache.felix.framework.Felix.getService(Felix.java:3568) >>> >>> >>> at >>> org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:468) >>> >>> >>> at >>> org.apache.axis2.osgi.deployment.OSGiConfigurationContextFactory$AxisConfigServiceListener.serviceChanged(OSGiConfigurationContextFactory.java:223) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543) >>> >>> >>> at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4419) >>> >>> >>> at org.apache.felix.framework.Felix.registerService(Felix.java:3423) >>> >>> >>> at >>> org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:919) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:908) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:134) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:960) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:755) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:709) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:655) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1477) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1398) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:1210) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:1148) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1429) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543) >>> >>> >>> at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4419) >>> >>> >>> at org.apache.felix.framework.Felix.registerService(Felix.java:3423) >>> >>> >>> at >>> org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:919) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:908) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:134) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:960) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:755) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:709) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager$SingleDynamicCustomizer.addedService(DependencyManager.java:655) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1477) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1398) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.trackAdding(ServiceTracker.java:1210) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$AbstractTracked.track(ServiceTracker.java:1148) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:1429) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793) >>> >>> >>> at >>> org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543) >>> >>> >>> at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4419) >>> >>> >>> at org.apache.felix.framework.Felix.registerService(Felix.java:3423) >>> >>> >>> at >>> org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346) >>> >>> >>> at >>> org.apache.felix.http.base.internal.HttpServiceController.register(HttpServiceController.java:135) >>> >>> >>> at >>> org.apache.felix.http.base.internal.DispatcherServlet.init(DispatcherServlet.java:48) >>> >>> >>> at >>> org.apache.felix.http.proxy.DispatcherTracker.initDispatcher(DispatcherTracker.java:97) >>> >>> >>> at >>> org.apache.felix.http.proxy.DispatcherTracker.setDispatcher(DispatcherTracker.java:77) >>> >>> >>> at >>> org.apache.felix.http.proxy.DispatcherTracker.addingService(DispatcherTracker.java:52) >>> >>> >>> at >>> org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:932) >>> >>> >>> at >>> org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:864) >>> >>> >>> at >>> org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) >>> >>> >>> at >>> org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) >>> >>> >>> at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:317) >>> >>> >>> at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261) >>> >>> >>> at org.apache.felix.http.proxy.ProxyServlet.doInit(ProxyServlet.java:51) >>> >>> >>> at org.apache.felix.http.proxy.ProxyServlet.init(ProxyServlet.java:39) >>> >>> >>> at >>> org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1280) >>> >>> >>> at >>> org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1193) >>> >>> >>> at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1088) >>> >>> >>> at >>> org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5123) >>> >>> >>> at >>> org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5407) >>> >>> >>> at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) >>> >>> >>> at >>> org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1559) >>> >>> >>> at >>> org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1549) >>> >>> >>> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) >>> >>> >>> at java.util.concurrent.FutureTask.run(FutureTask.java:166) >>> >>> >>> at >>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) >>> >>> >>> at >>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) >>> >>> >>> at java.lang.Thread.run(Thread.java:722) >>> >>> Caused by: java.lang.NullPointerException >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1746) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:1500) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ImmediateComponentManager.createImplementationObject(ImmediateComponentManager.java:276) >>> >>> >>> at >>> org.apache.felix.scr.impl.manager.ServiceFactoryComponentManager.getService(ServiceFactoryComponentManager.java:139) >>> >>> >>> at >>> org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:308) >>> >>> >>> ... 85 more >> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: [email protected] >> For additional commands, e-mail: [email protected] >> >
