Details

      Description

      We've been encountering several exceptions thrown intermittently from DS. They generally look like ungetting service on a disposed-of SCR BundleComponentActivator, ComponentManager, or DependencyManager. There may be two threads trying to shut down the same bundles at the same time. I'm not sure how to investigate the root cause or if this kind of behavior is expected. The SCR code generally doesn't look very thread safe. It's easy to "fix" the specific problems we see by adding more checks to the SCR code so the NPEs are avoided, or attempted use of closed bundle contexts are caught and ignored. I'd be happy to keep looking into this but could use some hints about what should be happening. Unless someone can come up with a better explanation and fix it would be great meanwhile to patch the code to avoid throwing the exceptions.

      Here are some of the typical stack traces we see:

      Stack Dump = org.osgi.framework.ServiceException: Exception in org.apache.felix.scr.impl.manager.DelayedComponentManager.ungetService()
      at org.eclipse.osgi.internal.serviceregistry.ServiceUse.releaseService(ServiceUse.java:287)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.releaseService(ServiceRegistrationImpl.java:562)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.releaseServicesInUse(ServiceRegistry.java:665)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.close(BundleContextImpl.java:91)
      at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:514)
      at org.eclipse.osgi.framework.internal.core.AbstractBundle.suspend(AbstractBundle.java:565)
      at org.eclipse.osgi.framework.internal.core.Framework.suspendBundle(Framework.java:1161)
      at org.eclipse.osgi.framework.internal.core.StartLevelManager.decFWSL(StartLevelManager.java:595)
      at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:257)
      at org.eclipse.osgi.framework.internal.core.StartLevelManager.shutdown(StartLevelManager.java:215)
      at org.eclipse.osgi.framework.internal.core.InternalSystemBundle.suspend(InternalSystemBundle.java:284)
      at org.eclipse.osgi.framework.internal.core.Framework.shutdown(Framework.java:691)
      at org.eclipse.osgi.framework.internal.core.Framework.close(Framework.java:598)
      at org.eclipse.osgi.framework.internal.core.InternalSystemBundle$1.run(InternalSystemBundle.java:261)
      at java.lang.Thread.run(Thread.java:680)
      Caused by: java.lang.NullPointerException
      at org.apache.felix.scr.impl.BundleComponentActivator.log(BundleComponentActivator.java:614)
      at org.apache.felix.scr.impl.BundleComponentActivator.log(BundleComponentActivator.java:589)
      at org.apache.felix.scr.impl.manager.AbstractComponentManager.log(AbstractComponentManager.java:633)
      at org.apache.felix.scr.impl.manager.AbstractComponentManager$State.log(AbstractComponentManager.java:1000)
      at org.apache.felix.scr.impl.manager.AbstractComponentManager$State.ungetService(AbstractComponentManager.java:964)
      at org.apache.felix.scr.impl.manager.DelayedComponentManager.ungetService(DelayedComponentManager.java:114)
      at org.eclipse.osgi.internal.serviceregistry.ServiceUse$3.run(ServiceUse.java:277)
      at java.security.AccessController.doPrivileged(Native Method)
      at org.eclipse.osgi.internal.serviceregistry.ServiceUse.releaseService(ServiceUse.java:275)
      ... 14 more

      Stack Dump = org.osgi.framework.ServiceException: Exception in org.apache.felix.scr.impl.manager.DelayedComponentManager.ungetService()
      at org.eclipse.osgi.internal.serviceregistry.ServiceUse.releaseService(ServiceUse.java:287)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.releaseService(ServiceRegistrationImpl.java:562)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:245)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.unregisterServices(ServiceRegistry.java:635)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.close(BundleContextImpl.java:88)
      at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:514)
      at org.eclipse.osgi.framework.internal.core.AbstractBundle.suspend(AbstractBundle.java:565)
      at org.eclipse.osgi.framework.internal.core.Framework.suspendBundle(Framework.java:1161)
      at org.eclipse.osgi.framework.internal.core.StartLevelManager.decFWSL(StartLevelManager.java:595)
      at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:257)
      at org.eclipse.osgi.framework.internal.core.StartLevelManager.shutdown(StartLevelManager.java:215)
      at org.eclipse.osgi.framework.internal.core.InternalSystemBundle.suspend(InternalSystemBundle.java:284)
      at org.eclipse.osgi.framework.internal.core.Framework.shutdown(Framework.java:691)
      at org.eclipse.osgi.framework.internal.core.Framework.close(Framework.java:598)
      at org.eclipse.osgi.framework.internal.core.InternalSystemBundle$1.run(InternalSystemBundle.java:261)
      at java.lang.Thread.run(Thread.java:680)
      Caused by: java.lang.IllegalStateException: BundleContext is no longer valid
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:931)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.ungetService(BundleContextImpl.java:634)
      at org.apache.felix.scr.impl.manager.DependencyManager.ungetService(DependencyManager.java:819)
      at org.apache.felix.scr.impl.manager.DependencyManager.unbind(DependencyManager.java:1000)
      at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:880)
      at org.apache.felix.scr.impl.manager.ImmediateComponentManager.disposeImplementationObject(ImmediateComponentManager.java:268)
      at org.apache.felix.scr.impl.manager.ImmediateComponentManager.deleteComponent(ImmediateComponentManager.java:135)
      at org.apache.felix.scr.impl.manager.DelayedComponentManager.deleteComponent(DelayedComponentManager.java:67)
      at org.apache.felix.scr.impl.manager.AbstractComponentManager$Active.ungetService(AbstractComponentManager.java:1266)
      at org.apache.felix.scr.impl.manager.DelayedComponentManager.ungetService(DelayedComponentManager.java:114)
      at org.eclipse.osgi.internal.serviceregistry.ServiceUse$3.run(ServiceUse.java:277)
      at java.security.AccessController.doPrivileged(Native Method)
      at org.eclipse.osgi.internal.serviceregistry.ServiceUse.releaseService(ServiceUse.java:275)
      ... 15 more

      -------
      This one is from FELIX-3307:

      java.lang.NullPointerException
      at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1028)
      at org.apache.felix.scr.impl.manager.DependencyManager.serviceAdded(DependencyManager.java:308)
      at org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:170)
      at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:104)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
      at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
      at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130)
      at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:451)
      at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:950)

      1. FELIX-3345-5.diff
        2 kB
        David Jencks
      2. FELIX-3345-4.diff
        85 kB
        David Jencks
      3. FELIX-3345-3.diff
        88 kB
        David Jencks
      4. FELIX-3345-2.diff
        8 kB
        David Jencks
      5. FELIX-3345.diff
        5 kB
        David Jencks

        Issue Links

          Activity

          Hide
          David Jencks added a comment -

          Detect and avoid error conditions, without much attempt to understand their cause.

          Show
          David Jencks added a comment - Detect and avoid error conditions, without much attempt to understand their cause.
          Hide
          David Jencks added a comment -

          Here are a couple more stack traces:

          Stack Dump = java.lang.IllegalStateException: BundleContext is no longer valid
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:931)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.ungetService(BundleContextImpl.java:634)
          at org.apache.felix.scr.impl.config.ConfigurationSupport.configureComponentHolder(ConfigurationSupport.java:112)
          at org.apache.felix.scr.impl.ComponentRegistry.createComponentHolder(ComponentRegistry.java:437)
          at org.apache.felix.scr.impl.BundleComponentActivator.loadDescriptor(BundleComponentActivator.java:232)
          at org.apache.felix.scr.impl.BundleComponentActivator.initialize(BundleComponentActivator.java:147)
          at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:111)
          at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:274)
          at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:192)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847)
          at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
          at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
          at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1523)
          at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1459)
          at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1454)
          at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:391)
          at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:299)
          //some management code is trying to start a bundle here

          Stack Dump = org.osgi.framework.BundleException: Exception in org.apache.felix.scr.impl.Activator.stop() of bundle org.apache.felix.scr.
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.stop(BundleContextImpl.java:791)
          at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:510)
          at org.eclipse.osgi.framework.internal.core.AbstractBundle.suspend(AbstractBundle.java:565)
          at org.eclipse.osgi.framework.internal.core.Framework.suspendBundle(Framework.java:1161)
          at org.eclipse.osgi.framework.internal.core.StartLevelManager.decFWSL(StartLevelManager.java:595)
          at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:257)
          at org.eclipse.osgi.framework.internal.core.StartLevelManager.shutdown(StartLevelManager.java:215)
          at org.eclipse.osgi.framework.internal.core.InternalSystemBundle.suspend(InternalSystemBundle.java:284)
          at org.eclipse.osgi.framework.internal.core.Framework.shutdown(Framework.java:691)
          at org.eclipse.osgi.framework.internal.core.Framework.close(Framework.java:598)
          at org.eclipse.osgi.framework.internal.core.InternalSystemBundle$1.run(InternalSystemBundle.java:261)
          at java.lang.Thread.run(Thread.java:680)
          Caused by: java.lang.IllegalStateException: BundleContext is no longer valid
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:931)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getBundle(BundleContextImpl.java:121)
          at org.apache.felix.scr.impl.Activator.disposeAllComponents(Activator.java:355)
          at org.apache.felix.scr.impl.Activator.stop(Activator.java:142)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl$2.run(BundleContextImpl.java:771)
          at java.security.AccessController.doPrivileged(Native Method)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.stop(BundleContextImpl.java:764)
          ... 11 more

          Show
          David Jencks added a comment - Here are a couple more stack traces: Stack Dump = java.lang.IllegalStateException: BundleContext is no longer valid at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:931) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.ungetService(BundleContextImpl.java:634) at org.apache.felix.scr.impl.config.ConfigurationSupport.configureComponentHolder(ConfigurationSupport.java:112) at org.apache.felix.scr.impl.ComponentRegistry.createComponentHolder(ComponentRegistry.java:437) at org.apache.felix.scr.impl.BundleComponentActivator.loadDescriptor(BundleComponentActivator.java:232) at org.apache.felix.scr.impl.BundleComponentActivator.initialize(BundleComponentActivator.java:147) at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:111) at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:274) at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:192) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1523) at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1459) at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1454) at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:391) at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:299) //some management code is trying to start a bundle here Stack Dump = org.osgi.framework.BundleException: Exception in org.apache.felix.scr.impl.Activator.stop() of bundle org.apache.felix.scr. at org.eclipse.osgi.framework.internal.core.BundleContextImpl.stop(BundleContextImpl.java:791) at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:510) at org.eclipse.osgi.framework.internal.core.AbstractBundle.suspend(AbstractBundle.java:565) at org.eclipse.osgi.framework.internal.core.Framework.suspendBundle(Framework.java:1161) at org.eclipse.osgi.framework.internal.core.StartLevelManager.decFWSL(StartLevelManager.java:595) at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:257) at org.eclipse.osgi.framework.internal.core.StartLevelManager.shutdown(StartLevelManager.java:215) at org.eclipse.osgi.framework.internal.core.InternalSystemBundle.suspend(InternalSystemBundle.java:284) at org.eclipse.osgi.framework.internal.core.Framework.shutdown(Framework.java:691) at org.eclipse.osgi.framework.internal.core.Framework.close(Framework.java:598) at org.eclipse.osgi.framework.internal.core.InternalSystemBundle$1.run(InternalSystemBundle.java:261) at java.lang.Thread.run(Thread.java:680) Caused by: java.lang.IllegalStateException: BundleContext is no longer valid at org.eclipse.osgi.framework.internal.core.BundleContextImpl.checkValid(BundleContextImpl.java:931) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getBundle(BundleContextImpl.java:121) at org.apache.felix.scr.impl.Activator.disposeAllComponents(Activator.java:355) at org.apache.felix.scr.impl.Activator.stop(Activator.java:142) at org.eclipse.osgi.framework.internal.core.BundleContextImpl$2.run(BundleContextImpl.java:771) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.stop(BundleContextImpl.java:764) ... 11 more
          Hide
          David Jencks added a comment -

          This patch includes the previous one and works around the 2 additional problems

          Show
          David Jencks added a comment - This patch includes the previous one and works around the 2 additional problems
          Hide
          David Jencks added a comment -

          I've finally managed to reproduce a similar problem in a test. The attached includes a lot of logging additions to scr, ignores the existing integration tests, and adds one that demonstrates a similar problem. It also always fails for unrelated reasons. The interesting stack trace is

          java.lang.NullPointerException: No log service
          at org.apache.felix.scr.impl.BundleComponentActivator.log(BundleComponentActivator.java:623)
          at org.apache.felix.scr.impl.BundleComponentActivator.log(BundleComponentActivator.java:594)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager.log(AbstractComponentManager.java:635)
          at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:596)
          at org.apache.felix.scr.impl.helper.BaseMethod$NotResolved.invoke(BaseMethod.java:552)
          at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:476)
          at org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:36)
          at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1142)
          at org.apache.felix.scr.impl.manager.DependencyManager.unbind(DependencyManager.java:999)
          at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:886)
          at org.apache.felix.scr.impl.manager.ImmediateComponentManager.disposeImplementationObject(ImmediateComponentManager.java:269)
          at org.apache.felix.scr.impl.manager.ImmediateComponentManager.deleteComponent(ImmediateComponentManager.java:135)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager$Satisfied.deactivate(AbstractComponentManager.java:1225)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:339)
          at org.apache.felix.scr.impl.manager.DependencyManager.serviceRemoved(DependencyManager.java:346)
          at org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:253)
          at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:104)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
          at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
          at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
          at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
          at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
          at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:225)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterComponentService(AbstractComponentManager.java:567)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager$Satisfied.deactivate(AbstractComponentManager.java:1224)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager.disposeInternal(AbstractComponentManager.java:360)
          at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:197)
          at org.apache.felix.scr.impl.config.ImmediateComponentHolder.disposeComponents(ImmediateComponentHolder.java:356)
          at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:312)
          at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:333)
          at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:198)
          at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847)
          at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
          at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
          at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1523)
          at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1459)
          at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1454)
          at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:506)
          at org.eclipse.osgi.framework.internal.core.AbstractBundle.stop(AbstractBundle.java:464)
          at org.eclipse.osgi.framework.internal.core.AbstractBundle.stop(AbstractBundle.java:456)
          at org.apache.felix.scr.integration.concurrency.ConcurrentShutdownTest$Worker.run(ConcurrentShutdownTest.java:185)
          at java.lang.Thread.run(Thread.java:680)

          By messing with the timing I've gotten into a state where we're trying to log on a BundleComponentActivator that has been shut down. The activity being logged is different, but the NPE is the same. Admittedly I added the log statement in question....

          The basic scenario is two threads shutting stuff down concurrently, and an unbind method that takes a long time to return.

          bundle A has a service s1
          bundle B has a service s2 with a reference to s1, and an unbind method that takes a long time.

          Stop A in thread 1; the thread gets stuck in unbind of s2.

          Stop B in thread 2; this shuts down B so it's BundleComponentActivator no longer can log (the NPE).

          If the unbind method in thread 1 now returns, it will try to log in B's BCA which has no log service tracker.

          If you comment out my added logging statement you get a different NPE.

          Show
          David Jencks added a comment - I've finally managed to reproduce a similar problem in a test. The attached includes a lot of logging additions to scr, ignores the existing integration tests, and adds one that demonstrates a similar problem. It also always fails for unrelated reasons. The interesting stack trace is java.lang.NullPointerException: No log service at org.apache.felix.scr.impl.BundleComponentActivator.log(BundleComponentActivator.java:623) at org.apache.felix.scr.impl.BundleComponentActivator.log(BundleComponentActivator.java:594) at org.apache.felix.scr.impl.manager.AbstractComponentManager.log(AbstractComponentManager.java:635) at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:596) at org.apache.felix.scr.impl.helper.BaseMethod$NotResolved.invoke(BaseMethod.java:552) at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:476) at org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:36) at org.apache.felix.scr.impl.manager.DependencyManager.invokeUnbindMethod(DependencyManager.java:1142) at org.apache.felix.scr.impl.manager.DependencyManager.unbind(DependencyManager.java:999) at org.apache.felix.scr.impl.manager.DependencyManager.close(DependencyManager.java:886) at org.apache.felix.scr.impl.manager.ImmediateComponentManager.disposeImplementationObject(ImmediateComponentManager.java:269) at org.apache.felix.scr.impl.manager.ImmediateComponentManager.deleteComponent(ImmediateComponentManager.java:135) at org.apache.felix.scr.impl.manager.AbstractComponentManager$Satisfied.deactivate(AbstractComponentManager.java:1225) at org.apache.felix.scr.impl.manager.AbstractComponentManager.deactivateInternal(AbstractComponentManager.java:339) at org.apache.felix.scr.impl.manager.DependencyManager.serviceRemoved(DependencyManager.java:346) at org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:253) at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:104) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819) at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771) at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:225) at org.apache.felix.scr.impl.manager.AbstractComponentManager.unregisterComponentService(AbstractComponentManager.java:567) at org.apache.felix.scr.impl.manager.AbstractComponentManager$Satisfied.deactivate(AbstractComponentManager.java:1224) at org.apache.felix.scr.impl.manager.AbstractComponentManager.disposeInternal(AbstractComponentManager.java:360) at org.apache.felix.scr.impl.manager.AbstractComponentManager.dispose(AbstractComponentManager.java:197) at org.apache.felix.scr.impl.config.ImmediateComponentHolder.disposeComponents(ImmediateComponentHolder.java:356) at org.apache.felix.scr.impl.BundleComponentActivator.dispose(BundleComponentActivator.java:312) at org.apache.felix.scr.impl.Activator.disposeComponents(Activator.java:333) at org.apache.felix.scr.impl.Activator.bundleChanged(Activator.java:198) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1523) at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1459) at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1454) at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:506) at org.eclipse.osgi.framework.internal.core.AbstractBundle.stop(AbstractBundle.java:464) at org.eclipse.osgi.framework.internal.core.AbstractBundle.stop(AbstractBundle.java:456) at org.apache.felix.scr.integration.concurrency.ConcurrentShutdownTest$Worker.run(ConcurrentShutdownTest.java:185) at java.lang.Thread.run(Thread.java:680) By messing with the timing I've gotten into a state where we're trying to log on a BundleComponentActivator that has been shut down. The activity being logged is different, but the NPE is the same. Admittedly I added the log statement in question.... The basic scenario is two threads shutting stuff down concurrently, and an unbind method that takes a long time to return. bundle A has a service s1 bundle B has a service s2 with a reference to s1, and an unbind method that takes a long time. Stop A in thread 1; the thread gets stuck in unbind of s2. Stop B in thread 2; this shuts down B so it's BundleComponentActivator no longer can log (the NPE). If the unbind method in thread 1 now returns, it will try to log in B's BCA which has no log service tracker. If you comment out my added logging statement you get a different NPE.
          Hide
          David Jencks added a comment -

          This is the same test but I removed all the stuff that didn't work. I had to modify ds logging to always use system.out since I don't understand how to get it to use pax-logging in the test.

          To be clear, this test is not in a committable form but should provide a way to see a concurrency problem repeatedly.

          Show
          David Jencks added a comment - This is the same test but I removed all the stuff that didn't work. I had to modify ds logging to always use system.out since I don't understand how to get it to use pax-logging in the test. To be clear, this test is not in a committable form but should provide a way to see a concurrency problem repeatedly.
          Hide
          David Jencks added a comment -

          Patch that fixes the underlying NPE from the concurrency test, that we have also run into in production.

          Show
          David Jencks added a comment - Patch that fixes the underlying NPE from the concurrency test, that we have also run into in production.
          Hide
          Felix Meschberger added a comment - - edited

          Thanks for providing the patches. As indicated in [1] I have applied the patches as follows:

          FELIX-3345-2.diff in Rev. 1298266
          FELIX-3345-5.diff in Rev. 1298267

          Patch FELIX-3345-6.diff referred to in the message seems to be missing. Doesn't matter, I'd like to apply the comprehensive test patch as of FELIX-3371 anyway.

          [1] http://markmail.org/message/zzf4tjuky6wxm3v2

          Show
          Felix Meschberger added a comment - - edited Thanks for providing the patches. As indicated in [1] I have applied the patches as follows: FELIX-3345 -2.diff in Rev. 1298266 FELIX-3345 -5.diff in Rev. 1298267 Patch FELIX-3345 -6.diff referred to in the message seems to be missing. Doesn't matter, I'd like to apply the comprehensive test patch as of FELIX-3371 anyway. [1] http://markmail.org/message/zzf4tjuky6wxm3v2
          Hide
          Felix Meschberger added a comment -

          What about the patches 3 and 4 ? Should these also be applied ? Are there any differences between them ?

          Show
          Felix Meschberger added a comment - What about the patches 3 and 4 ? Should these also be applied ? Are there any differences between them ?
          Hide
          Felix Meschberger added a comment -

          What is the relationship of this issue with FELIX-3456 ?

          Is this still reproducible ?

          Show
          Felix Meschberger added a comment - What is the relationship of this issue with FELIX-3456 ? Is this still reproducible ?
          Hide
          David Jencks added a comment -

          The relevant patches were all applied well before 1.6.2 was released

          Show
          David Jencks added a comment - The relevant patches were all applied well before 1.6.2 was released

            People

            • Assignee:
              Felix Meschberger
              Reporter:
              David Jencks
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development