I forgot to respond to your question: everything is built using j8 because we would like to use java8 for our next DM release. But I just temporarily commited a fix for ds and ds.itest modules in order to build with java7, just to make sure that the issue does not come from java8. And as said in the previous mail, I also reproduce the problem with java7.
thank you /Pierre On Sat, Aug 1, 2015 at 11:52 PM, Pierre De Rop <[email protected]> wrote: > I just commited in order to build the > org.apache.felix.dependencymanager.ds and > org.apache.felix.dependencymanager.ds.itest modules with java7. > > also, I added a trace in the A.java class in order to log the current > thread from the activate method. > > I did not yet try to launch gradlew multiple times, I will do that. In the > meantime, even using java7, under eclipse I did reproduce the problem by > doing this: > > - under eclipse: open the > org.apache.felix.dependencymanager.ds.itest/src/org/apache/felix/scr/integration/CircularReferenceTest.java > > - then click on the class name (in the code), and then click right, and > then click on "Run As" -> "Bnd OSGi Test Launcher (Junit)". > > - After running the tests for CircularReferenceTest.java a couple of times > (three times), then I got a failure for the > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_delayed_B_first > test. > > Here are the traces (see my comments after the traces): > > > ------------------------------------------------------------------------------------------------------------------------------------------------------------ > INFO : org.apache.felix.dependencymanager.ds (4): Starting with > globalExtender setting: false > INFO : org.apache.felix.dependencymanager.ds (4): Version = 1.0.0 > DEBUG: Starting ComponentActorThread > DEBUG: org.apache.felix.framework (0): Starting extension synchronously > bundle: org.apache.felix.framework/0 > DEBUG: org.apache.felix.metatype (1): Starting extension synchronously > bundle: org.apache.felix.metatype/1 > DEBUG: org.apache.felix.gogo.runtime (2): Starting extension synchronously > bundle: org.apache.felix.gogo.runtime/2 > DEBUG: org.apache.felix.configadmin (3): Starting extension synchronously > bundle: org.apache.felix.configadmin/3 > DEBUG: org.apache.felix.dependencymanager.ds (4): Starting extension > synchronously bundle: org.apache.felix.dependencymanager.ds/4 > DEBUG: org.apache.felix.gogo.command (5): Starting extension synchronously > bundle: org.apache.felix.gogo.command/5 > DEBUG: org.apache.felix.gogo.shell (6): Starting extension synchronously > bundle: org.apache.felix.gogo.shell/6 > DEBUG: org.apache.felix.shell (7): Starting extension synchronously > bundle: org.apache.felix.shell/7 > DEBUG: biz.aQute.bndlib (8): Starting extension synchronously bundle: > biz.aQute.bndlib/8 > DEBUG: org.apache.felix.dependencymanager.ds.itest (9): Starting extension > synchronously bundle: org.apache.felix.dependencymanager.ds.itest/9 > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_immediate_B_first > ____________________________ > Welcome to Apache Felix Gogo > > g! L=1 D=23:19:58,746 T="main" (log expected): [2.A.1.1.dynamic(2)] > Circular reference detected, getService returning null > L=2 D=23:19:58,756 T="main" (log expected): [2.B.0.n.dynamic(3)] Could not > get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:19:58,756 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@6b223cc6 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@264c1c97 > ) > main:A.activate > L=1 D=23:19:58,799 T="main" (log expected): [5.A.1.1.dynamic(10)] Circular > reference detected, getService returning null > L=1 D=23:19:58,805 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:19:58,806 T="main" (log expected): [5.B.0.1.dynamic(11)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@69014ca9 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@4bdc0b6b > ) > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@6b223cc6 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@264c1c97 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@69014ca9 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@4bdc0b6b > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B0n_immediate_B_first > L=1 D=23:19:58,901 T="main" (log expected): [2.A.1.1.dynamic(20)] Circular > reference detected, getService returning null > L=1 D=23:19:58,907 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned > null.main:A.setB(org.apache.felix.scr.integration.components.circular.B@2b9dbab0 > ) > main:A.activate > > main:A.setB(org.apache.felix.scr.integration.components.circular.B@12206e16 > ) > main:A.activate > L=2 D=23:19:58,907 T="main" (log expected): [2.B.0.n.dynamic(21)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:19:58,929 T="main" (log expected): [5.A.1.1.dynamic(28)] Circular > reference detected, getService returning null > main:A.setB(org.apache.felix.scr.integration.components.circular.B@26a40607 > ) > main:A.activate > L=1 D=23:19:58,935 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:19:58,935 T="main" (log expected): [5.B.0.1.dynamic(29)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@5fb155b7 > ) > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@2b9dbab0 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@12206e16 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@26a40607 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@5fb155b7 > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_delayed_A_first > L=1 D=23:19:59,29 T="main" (log expected): [2.A.1.1.dynamic(38)] Circular > reference detected, getService returning null > L=1 D=23:19:59,37 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@56a45c4 > ) > main:A.activate > L=2 D=23:19:59,37 T="main" (log expected): [2.B.0.n.dynamic(39)] Could not > get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@7972ccd6 > ) > main:A.activate > L=1 D=23:19:59,52 T="main" (log expected): [5.A.1.1.dynamic(46)] Circular > reference detected, getService returning null > L=1 D=23:19:59,59 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:19:59,59 T="main" (log expected): [5.B.0.1.dynamic(47)] Could not > get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@67d871ab > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@6ce669f3 > ) > main:A.activate > L=2 D=23:19:59,71 T="main" (log expected): [7.1.B.0.1.dynamic(51)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@58a35603 > ) > L=1 D=23:19:59,71 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: ServiceFactory.getService() resulted > in a cycle. > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@56a45c4 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@7972ccd6 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@67d871ab > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@6ce669f3 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@58a35603 > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_delayed_B_first > L=1 D=23:19:59,470 T="main" (log expected): [2.A.1.1.dynamic(56)] Circular > reference detected, getService returning null > L=1 D=23:19:59,482 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:19:59,482 T="main" (log expected): [2.B.0.n.dynamic(57)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@711a2c8f > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@30ea0dfc > ) > main:A.activate > L=1 D=23:19:59,499 T="main" (log expected): [5.A.1.1.dynamic(64)] Circular > reference detected, getService returning null > L=1 D=23:19:59,510 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:19:59,510 T="main" (log expected): [5.B.0.1.dynamic(65)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@2c146877 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@685d72cd > ) > main:A.activate > L=2 D=23:19:59,531 T="main" (log expected): [7.2.A.1.1.dynamic(70)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.B] > L=1 D=23:19:59,531 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: ServiceFactory.getService() resulted > in a cycle. > L=1 D=23:19:59,531 T="main" (log expected): [7.2.A.1.1.dynamic(70)] Cannot > create component instance due to failure to bind reference b > L=1 D=23:19:59,531 T="main" (log expected): [7.2.A.1.1.dynamic(70)] Failed > creating the component instance; see log for reason > main:A.setB(org.apache.felix.scr.integration.components.circular.B@11c757a1 > ) > main:A.activate > L=2 D=23:19:59,531 T="main" (log expected): [7.2.B.0.1.dynamic(71)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > SCR Component > Actor:A.setB(org.apache.felix.scr.integration.components.circular.B@11c757a1 > ) > L=1 D=23:19:59,533 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > detected problem ... > stack traces when B was bound: > java.lang.Exception > at > org.apache.felix.scr.integration.components.circular.A.setB(A.java:49) > at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at > org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222) > at > org.apache.felix.scr.impl.helper.BaseMethod.access$1(BaseMethod.java:212) > at > org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615) > at > org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499) > at > org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:1) > at > org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1653) > at > org.apache.felix.scr.impl.manager.DependencyManager.open(DependencyManager.java:1491) > at > org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:265) > at > org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:113) > at > org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:847) > at > org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:814) > at > org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:763) > at > org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:347) > at > org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:247) > at > org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:343) > at org.apache.felix.framework.Felix.getService(Felix.java:3692) > at > org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:470) > at > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_delayed_B_first(CircularReferenceTest.java:255) > 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:606) > at junit.framework.TestCase.runTest(TestCase.java:176) > at junit.framework.TestCase.runBare(TestCase.java:141) > at junit.framework.TestResult$1.protect(TestResult.java:122) > at junit.framework.TestResult.runProtected(TestResult.java:142) > at junit.framework.TestResult.run(TestResult.java:125) > at junit.framework.TestCase.run(TestCase.java:129) > at junit.framework.TestSuite.runTest(TestSuite.java:255) > at junit.framework.TestSuite.run(TestSuite.java:250) > at junit.framework.TestSuite.runTest(TestSuite.java:255) > at junit.framework.TestSuite.run(TestSuite.java:250) > at aQute.junit.Activator.test(Activator.java:303) > at aQute.junit.Activator.run(Activator.java:128) > at aQute.launcher.Launcher$5.call(Launcher.java:1175) > at aQute.launcher.Launcher$5.call(Launcher.java:1173) > at aQute.launcher.Launcher.run(Launcher.java:278) > at aQute.launcher.Launcher.main(Launcher.java:87) > java.lang.Exception > at > org.apache.felix.scr.integration.components.circular.A.setB(A.java:49) > at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at > org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222) > at > org.apache.felix.scr.impl.helper.BaseMethod.access$1(BaseMethod.java:212) > at > org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615) > at > org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499) > at > org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:1) > at > org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1653) > at > org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1629) > at > org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:370) > at > org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethodLate(DependencyManager.java:1573) > at > org.apache.felix.scr.impl.ComponentRegistry$1.run(ComponentRegistry.java:570) > at > org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:99) > at java.lang.Thread.run(Thread.java:745) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@711a2c8f > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@30ea0dfc > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@2c146877 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@685d72cd > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@11c757a1 > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B0n_delayed_A_first > L=1 D=23:19:59,908 T="main" (log expected): [2.A.1.1.dynamic(74)] Circular > reference detected, getService returning null > main:A.setB(org.apache.felix.scr.integration.components.circular.B@16d27e69 > ) > main:A.activate > L=1 D=23:19:59,918 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:19:59,918 T="main" (log expected): [2.B.0.n.dynamic(75)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@72d8c235 > ) > main:A.activate > L=1 D=23:19:59,928 T="main" (log expected): [5.A.1.1.dynamic(82)] Circular > reference detected, getService returning null > L=2 D=23:19:59,937 T="main" (log expected): [5.B.0.1.dynamic(83)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@17d33c09 > ) > L=1 D=23:19:59,937 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@28d3953f > ) > main:A.activate > L=1 D=23:20:00,246 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: ServiceFactory.getService() resulted > in a cycle. > L=2 D=23:20:00,246 T="main" (log expected): [4.1.B.0.n.dynamic(79)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@393f8181 > ) > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@16d27e69 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@72d8c235 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@393f8181 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@17d33c09 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@28d3953f > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_immediate_A_first > L=1 D=23:20:00,670 T="main" (log expected): [2.A.1.1.dynamic(92)] Circular > reference detected, getService returning null > L=2 D=23:20:00,673 T="main" (log expected): [2.B.0.n.dynamic(93)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:00,673 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@6783113b > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@472ae739 > ) > main:A.activate > L=1 D=23:20:00,682 T="main" (log expected): [5.A.1.1.dynamic(100)] > Circular reference detected, getService returning null > L=2 D=23:20:00,686 T="main" (log expected): [5.B.0.1.dynamic(101)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:00,686 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@4490bc23 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@2462ea85 > ) > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@6783113b > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@472ae739 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@4490bc23 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@2462ea85 > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B0n_immediate_A_first > L=1 D=23:20:00,750 T="main" (log expected): [2.A.1.1.dynamic(110)] > Circular reference detected, getService returning null > L=2 D=23:20:00,756 T="main" (log expected): [2.B.0.n.dynamic(111)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:00,756 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@373fdd1a > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@7aa25e73 > ) > main:A.activate > L=1 D=23:20:00,768 T="main" (log expected): [5.A.1.1.dynamic(118)] > Circular reference detected, getService returning null > L=2 D=23:20:00,774 T="main" (log expected): [5.B.0.1.dynamic(119)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:00,774 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@4f1e5ed9 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@e324105 > ) > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@373fdd1a > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@7aa25e73 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@4f1e5ed9 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@e324105 > ) > Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B0n_delayed_B_first > L=1 D=23:20:00,832 T="main" (log expected): [2.A.1.1.dynamic(128)] > Circular reference detected, getService returning null > L=2 D=23:20:00,840 T="main" (log expected): [2.B.0.n.dynamic(129)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:00,840 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@250fc185 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@69fa6743 > ) > main:A.activate > L=1 D=23:20:00,852 T="main" (log expected): [5.A.1.1.dynamic(136)] > Circular reference detected, getService returning null > L=1 D=23:20:00,860 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:20:00,860 T="main" (log expected): [5.B.0.1.dynamic(137)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@65536eb4 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@2c158f66 > ) > main:A.activate > L=1 D=23:20:00,873 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: ServiceFactory.getService() resulted > in a cycle. > L=2 D=23:20:00,873 T="main" (log expected): [4.2.A.1.1.dynamic(134)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.B] > L=1 D=23:20:00,874 T="main" (log expected): [4.2.A.1.1.dynamic(134)] > Cannot create component instance due to failure to bind reference b > L=1 D=23:20:00,874 T="main" (log expected): [4.2.A.1.1.dynamic(134)] > Failed creating the component instance; see log for reason > L=1 D=23:20:00,874 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > L=2 D=23:20:00,874 T="main" (log expected): [4.2.B.0.n.dynamic(135)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > main:A.setB(org.apache.felix.scr.integration.components.circular.B@946421a > ) > main:A.activate > SCR Component > Actor:A.unsetB(org.apache.felix.scr.integration.components.circular.B@946421a > ) > SCR Component > Actor:A.setB(org.apache.felix.scr.integration.components.circular.B@946421a > ) > SCR Component Actor:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@250fc185 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@69fa6743 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@946421a > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@65536eb4 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@2c158f66 > ) > Running org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B11 > L=1 D=23:20:01,844 T="main" (log expected): [2.A.1.1.dynamic(147)] > Circular reference detected, getService returning null > L=2 D=23:20:01,853 T="main" (log expected): [2.B.0.n.dynamic(148)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:01,853 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@6e69e35 > ) > main:A.activate > main:A.setB(org.apache.felix.scr.integration.components.circular.B@13b2fed8 > ) > main:A.activate > L=1 D=23:20:01,864 T="main" (log expected): [5.A.1.1.dynamic(155)] > Circular reference detected, getService returning null > main:A.setB(org.apache.felix.scr.integration.components.circular.B@70a51c12 > ) > main:A.activate > L=2 D=23:20:01,873 T="main" (log expected): [5.B.0.1.dynamic(156)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > L=1 D=23:20:01,873 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > main:A.setB(org.apache.felix.scr.integration.components.circular.B@1e884ca9 > ) > main:A.activate > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@6e69e35 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@13b2fed8 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@70a51c12 > ) > > main:A.unsetB(org.apache.felix.scr.integration.components.circular.B@1e884ca9 > ) > Tests run : 9 > Passed : 8 > Errors : 0 > Failures : 1 > > > ------------------------------------------------------------------------------------------------------------------------------------------------------------ > > So, you can look for the "Running > org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_delayed_B_first" > log, where the failing "test_A11_B01_delayed_B_first" is starting. > > a bit later, you see: > > ... > detected problem ... > stack traces when B was bound: > ... > > here, the "assertABoundToOneB(a)" method (called from line 261) has > detected that the A component has been bound twice to the same B instance, > and it then displays the two stack traces when "A.setB(B b)" was called > twice. > > Indeed, we see two logs when A.setB(B b) is called (before the error): > > --- > main:A.setB(org.apache.felix.scr.integration.components.circular.B@11c757a1 > ) > main:A.activate > L=2 D=23:19:59,531 T="main" (log expected): [7.2.B.0.1.dynamic(71)] Could > not get service from ref > [org.apache.felix.scr.integration.components.circular.A] > SCR Component > Actor:A.setB(org.apache.felix.scr.integration.components.circular.B@11c757a1 > ) > L=1 D=23:19:59,533 T="FelixDispatchQueue" (log expected): FrameworkEvent: > ERROR > org.osgi.framework.ServiceException: Service factory returned null. > detected problem ... > ... > --- > > So, A.setB is called first from the main thread (see the first strack > trace). > Then A.SetB is called a second time, but from the Component Actor thread > (see the second stacktrace). > > I have an idea of what is going on but I prefer to first let you analyze > the logs from your side. > > I hope that you will be able to reproduce this from eclipse. let me know. > > thanks. > > > On Sat, Aug 1, 2015 at 10:02 PM, David Jencks < > [email protected]> wrote: > >> I checked out your sandbox… >> >> I changed to java 1.7, is there a reason you want 1.8? >> >> I haven’t remembered how to get the tests to run in eclipse yet, but on >> java 7 running gradlew in the tests all the tests pass; I’ve tried 15 or 20 >> times by now. >> >> Can you collect the debug logging output from a failing run and get it to >> me somehow? Maybe I can decipher what is going wrong. >> >> thanks >> david jencks >> >> > On Jul 30, 2015, at 3:16 PM, Pierre De Rop <[email protected]> >> wrote: >> > >> > Hi David, >> > >> > Thanks, I just created the FELIX-4984 >> > <https://issues.apache.org/jira/browse/FELIX-4984> issue and described >> > everything in it. >> > >> > I have not yet modified the SCR core. I only ported SCR project to >> bndtools >> > and integrated it in the DM project. what I did so far is that I >> reworked >> > the SCR tests in order to not use anymore pax-exam and simply rely on >> > BndTools integration tests. >> > >> > So unless I did a mistake while reworking the tests, I think it's worth >> > that you take a look in case there is really a pending bug somewhere >> that >> > is sometimes reproduced by the CircularReferenceTest. >> > (I can't reproduce it using maven from the current felix-trunk/scr/). >> > >> > In the meantime, I will also continue to investigate. >> > >> > thank you. >> > /Pierre >> > >> > >> > >> > On Thu, Jul 30, 2015 at 6:49 AM, David Jencks <[email protected] >> > >> > wrote: >> > >> >> Hi Pierre, >> >> >> >> Please open a jira. I will try to look into this soon. >> >> >> >> I haven’t had much time lately but I would like to move the existing >> >> feliix DS to bndtools no matter whether your idea of making DM support >> DS >> >> works or not :-). Is your current work available somewhere? >> >> >> >> thanks >> >> david jencks >> >> >> >>> On Jul 29, 2015, at 6:53 PM, Pierre De Rop <[email protected]> >> >> wrote: >> >>> >> >>> Hello all; >> >>> >> >>> While working on FELIX-4955 >> >>> <https://issues.apache.org/jira/browse/FELIX-4955> I think I'm >> facing an >> >>> issue with the CircularReferenceTest in the SCR integration tests. >> >>> >> >>> Unfortunately, I can not currently reproduces this problem in the scr >> >>> maven/pax-exam environment. I can only (sometimes, not always) >> reproduce >> >> it >> >>> under bndtools in the context of FELIX-4955. >> >>> <https://issues.apache.org/jira/browse/FELIX-4955> >> >>> >> >>> The problem comes from the >> >>> CircularReferenceTest.test_A11_B01_delayed_B_first() method: >> sometimes, >> >>> this test fails because A component has been bound with two B >> instances >> >> and >> >>> the following assertion fails: >> >>> >> >>> assertEquals( 1, a.getBs().size()); >> >>> >> >>> I'm showing now the original code from the scr integration test: >> >>> >> >>> @Test >> >>> public void test_A11_B01_delayed_B_first() throws Exception >> >>> { >> >>> String componentNameA = "7.A.1.1.dynamic"; >> >>> ComponentConfigurationDTO componentA = >> >>> findComponentConfigurationByName( componentNameA, >> >>> ComponentConfigurationDTO.SATISFIED ); >> >>> >> >>> String componentNameB = "7.B.0.1.dynamic"; >> >>> final ComponentConfigurationDTO componentB = >> >>> findComponentConfigurationByName( componentNameB, >> >>> ComponentConfigurationDTO.SATISFIED ); >> >>> >> >>> ServiceReference[] serviceReferencesB = >> >>> bundleContext.getServiceReferences( B.class.getName(), >> "(service.pid=" + >> >>> componentNameB + ")" ); >> >>> TestCase.assertEquals( 1, serviceReferencesB.length ); >> >>> ServiceReference serviceReferenceB = serviceReferencesB[0]; >> >>> Object serviceB = bundleContext.getService( serviceReferenceB ); >> >>> assertNotNull( serviceB ); >> >>> >> >>> ServiceReference[] serviceReferencesA = >> >>> bundleContext.getServiceReferences( A.class.getName(), >> "(service.pid=" + >> >>> componentNameA + ")" ); >> >>> TestCase.assertEquals( 1, serviceReferencesA.length ); >> >>> ServiceReference serviceReferenceA = serviceReferencesA[0]; >> >>> Object serviceA = bundleContext.getService( serviceReferenceA ); >> >>> assertNotNull( serviceA ); >> >>> >> >>> >> >>> delay(); >> >>> A a = getServiceFromConfiguration(componentA, A.class); >> >>> >> >> >> ------------------------------------------------------------------------------------------------------------ >> >>> -> assertEquals( 1, a.getBs().size()); // this assert >> sometimes >> >>> fails and a.getBs().size() returns 2 >> >>> >> >> >> ------------------------------------------------------------------------------------------------------------ >> >>> B b = getServiceFromConfiguration(componentB, B.class); >> >>> assertEquals( 1, b.getAs().size() ); >> >>> >> >>> >> >>> //disabling (removing the A service registration) and >> re-enabling >> >>> will >> >>> //result in a service event to B, so B will bind A. >> >>> disableAndCheck(componentA); >> >>> delay(); >> >>> enableAndCheck(componentA.description); >> >>> delay(); >> >>> >> >>> //new component.id, refetch configuration. >> >>> componentA = findComponentConfigurationByName( componentNameA, >> >>> ComponentConfigurationDTO.ACTIVE ); >> >>> a = getServiceFromConfiguration(componentA, A.class); >> >>> assertEquals( 1, a.getBs().size()); >> >>> b = getServiceFromConfiguration(componentB, B.class); >> >>> assertEquals( 1, b.getAs().size() ); >> >>> >> >>> } >> >>> >> >>> Sometimes, the a.getBs().size() method returns 2 and this test fails. >> >>> >> >>> I have tried to make a diagnostic and here is my current >> understanding of >> >>> the problem: >> >>> >> >>> - I have added some logs in the A component like this: (a log is done >> >> when >> >>> A.setB(B b) is called, and the stacktrace call is stored in >> >> "bsStackTraces" >> >>> list: >> >>> >> >>> public class A >> >>> { >> >>> private List<B> bs = new ArrayList<B>(); >> >>> private List<Exception> bsStackTraces = new ArrayList<>(); >> >>> >> >>> private boolean activated; >> >>> >> >>> private void activate(ComponentContext cc) >> >>> { >> >>> activated = true; >> >>> } >> >>> >> >>> private void setB(B b) >> >>> { >> >>> System.out.println(Thread.currentThread().getName() + ":" + >> >>> "A.setB(" + b + ")"); >> >>> bs.add( b ); >> >>> bsStackTraces.add(new Exception()); >> >>> } >> >>> >> >>> private void unsetB(B b) >> >>> { >> >>> System.out.println(Thread.currentThread().getName() + ":" + >> >>> "A.unsetB(" + b + ")"); >> >>> bs.remove( b ); >> >>> bsStackTraces.remove(bsStackTraces.size()-1); >> >>> } >> >>> >> >>> public List<B> getBs() >> >>> { >> >>> return bs; >> >>> } >> >>> >> >>> public void dumpStackTracesWhenBWasBound() { >> >>> System.out.println("stack traces when B was bound:"); >> >>> for (Exception e : bsStackTraces) { >> >>> e.printStackTrace(); >> >>> } >> >>> } >> >>> } >> >>> >> >>> - so, under bndtools (in the context of FELIX-4955 >> >>> <https://issues.apache.org/jira/browse/FELIX-4955>), I see that >> >> A.setB(B b) >> >>> is called twice: >> >>> >> >>> >> >> >> main:A.setB(org.apache.felix.scr.integration.components.circular.B@192d43ce >> >> ) >> >>> SCR Component >> >>> >> >> >> Actor:A.setB(org.apache.felix.scr.integration.components.circular.B@192d43ce >> >>> ) >> >>> >> >>> here, a.setB(B b) is first called from the main thread, and called a >> >> second >> >>> time from the component actor thread. >> >>> >> >>> - now, from the test method, I have added this debug statement: >> >>> >> >>> @Test >> >>> public void test_A11_B01_delayed_B_first() throws Exception >> >>> { >> >>> String componentNameA = "7.2.A.1.1.dynamic"; >> >>> ComponentConfigurationDTO componentA = >> >>> findComponentConfigurationByName( componentNameA, >> >>> ComponentConfigurationDTO.SATISFIED ); >> >>> >> >>> String componentNameB = "7.2.B.0.1.dynamic"; >> >>> final ComponentConfigurationDTO componentB = >> >>> findComponentConfigurationByName( componentNameB, >> >>> ComponentConfigurationDTO.SATISFIED ); >> >>> >> >>> ServiceReference[] serviceReferencesB = >> >>> bundleContext.getServiceReferences( B.class.getName(), >> "(service.pid=" + >> >>> componentNameB + ")" ); >> >>> TestCase.assertEquals( 1, serviceReferencesB.length ); >> >>> ServiceReference serviceReferenceB = serviceReferencesB[0]; >> >>> Object serviceB = bundleContext.getService( serviceReferenceB ); >> >>> assertNotNull( serviceB ); >> >>> >> >>> ServiceReference[] serviceReferencesA = >> >>> bundleContext.getServiceReferences( A.class.getName(), >> "(service.pid=" + >> >>> componentNameA + ")" ); >> >>> TestCase.assertEquals( 1, serviceReferencesA.length ); >> >>> ServiceReference serviceReferenceA = serviceReferencesA[0]; >> >>> Object serviceA = bundleContext.getService( serviceReferenceA ); >> >>> assertNotNull( serviceA ); >> >>> >> >>> >> >>> delay(); >> >>> A a = getServiceFromConfiguration(componentA, A.class); >> >>> // TODO remove >> >>> if (a.getBs().size() != 1) { >> >>> System.err.println("detected problem ..."); >> >>> a.dumpStackTracesWhenBWasBound(); >> >>> } >> >>> assertEquals( 1, a.getBs().size()); >> >>> ... >> >>> >> >>> so, when a.getBs().size() does not return 1, we call >> >>> "a.dumpStackTracesWhenBWasBound()" and here are those stacktraces: >> >>> >> >>> stack traces when B was bound: >> >>> java.lang.Exception >> >>> at >> >>> org.apache.felix.scr.integration.components.circular.A.setB(A.java:48) >> >>> at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source) >> >>> at >> >>> >> >> >> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >> >>> at java.lang.reflect.Method.invoke(Method.java:497) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615) >> >>> at >> >>> >> org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499) >> >>> at >> >>> org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:41) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1653) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.DependencyManager.open(DependencyManager.java:1491) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:265) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:113) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:847) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:814) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:763) >> >>> at >> >>> >> >> >> org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:347) >> >>> at >> >>> >> >> >> org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:247) >> >>> at >> >>> >> >> >> org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:343) >> >>> at org.apache.felix.framework.Felix.getService(Felix.java:3692) >> >>> at >> >>> >> >> >> org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:470) >> >>> at >> >>> >> >> >> org.apache.felix.scr.integration.CircularReferenceTest.test_A11_B01_delayed_B_first(CircularReferenceTest.java:255) >> >>> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) >> >>> at >> >>> >> >> >> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) >> >>> at >> >>> >> >> >> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >> >>> at java.lang.reflect.Method.invoke(Method.java:497) >> >>> at junit.framework.TestCase.runTest(TestCase.java:176) >> >>> at junit.framework.TestCase.runBare(TestCase.java:141) >> >>> at junit.framework.TestResult$1.protect(TestResult.java:122) >> >>> at junit.framework.TestResult.runProtected(TestResult.java:142) >> >>> at junit.framework.TestResult.run(TestResult.java:125) >> >>> at junit.framework.TestCase.run(TestCase.java:129) >> >>> at junit.framework.TestSuite.runTest(TestSuite.java:255) >> >>> at junit.framework.TestSuite.run(TestSuite.java:250) >> >>> at junit.framework.TestSuite.runTest(TestSuite.java:255) >> >>> at junit.framework.TestSuite.run(TestSuite.java:250) >> >>> at aQute.junit.Activator.test(Activator.java:303) >> >>> at aQute.junit.Activator.run(Activator.java:128) >> >>> at aQute.launcher.Launcher$5.call(Launcher.java:1175) >> >>> at aQute.launcher.Launcher$5.call(Launcher.java:1173) >> >>> at aQute.launcher.Launcher.run(Launcher.java:278) >> >>> at aQute.launcher.Launcher.main(Launcher.java:87) >> >>> >> >>> java.lang.Exception >> >>> at >> >>> org.apache.felix.scr.integration.components.circular.A.setB(A.java:48) >> >>> at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source) >> >>> at >> >>> >> >> >> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >> >>> at java.lang.reflect.Method.invoke(Method.java:497) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615) >> >>> at >> >>> >> org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499) >> >>> at >> >>> org.apache.felix.scr.impl.helper.BindMethod.invoke(BindMethod.java:41) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:1653) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1629) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:370) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethodLate(DependencyManager.java:1573) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.ComponentRegistry$1.run(ComponentRegistry.java:570) >> >>> at >> >>> >> >> >> org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:99) >> >>> at java.lang.Thread.run(Thread.java:745) >> >>> >> >>> So, in the first stacktrace, a.setB(B b) is called when the >> >>> test_A11_B01_delayed_B_first method calls >> >>> "Object serviceA = bundleContext.getService( serviceReferenceA );" >> which >> >>> then calls SingleComponentManager.createComponent() method. And that >> >> method >> >>> then calls createImplementationObject which then opens the >> >>> DependencyManager, which then calls A.bind(A b). >> >>> >> >>> But now in the second stacktrace (which comes from the componen actor >> >>> thread), "A.setB(B b)" is called a second time because in the first >> >>> stacktrace, the SingleComponentManager.createComponent() method has >> >>> schedule a task in the actor thread like this: >> >>> >> >>> >> >>> if ( activator != null ) >> >>> { >> >>> activator.missingServicePresent( getServiceReference() >> ); >> >>> } >> >>> >> >>> and the missingServicePresent schedules in the ComponentActor thread a >> >> task >> >>> which then calls invokeBindLate, which then finally calls a second >> time >> >> the >> >>> A.bind(B b) method. >> >>> >> >>> Am I correct with this diagnostic ? Should I open a jira issue ? >> >>> >> >>> thank you; >> >>> /Pierre >> >> >> >> >> >> >
