felix-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Pierre De Rop <pierre.de...@gmail.com>
Subject Re: [SCR] issue in CircularReferenceTest ?
Date Sat, 01 Aug 2015 21:52:01 GMT
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 <
david_jencks@yahoo.com.invalid> 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 <pierre.derop@gmail.com>
> 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 <david.a.jencks@gmail.com>
> > 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 <pierre.derop@gmail.com>
> >> 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
> >>
> >>
>
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message