You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@felix.apache.org by David Jencks <da...@yahoo.com.INVALID> on 2015/08/01 22:02:01 UTC
Re: [SCR] issue in CircularReferenceTest ?
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 <pi...@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 <da...@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 <pi...@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
>>
>>
Re: [SCR] issue in CircularReferenceTest ?
Posted by Pierre De Rop <pi...@gmail.com>.
Hi David,
First, good to know you also are also a fan of BndTools. When you start
working with it, you can't go back to another environment tool :-). That
being said, I would be extremely happy to contribute to the porting of
current SCR. The work is almost done, and I could quickly create a jira
issue (in a couple of weeks because I'm currently in vacation) and attach
to it a bndtools based Scr project (including the scr.compat), as well as a
gradle script in order to make releases to Apache.
So, you could then look into all this and inspire of it if you want in
order to switch to bndtools. Pax-Exam is not used anymore and I'm using an
ultra simple class, based on bndlib, that allows to create "tiny bundles".
The only problem is that I have to manually upload binary artifacts to
maven central. But I consider it is an ultra-minor issue compared to the
huge benefit of developing/debugging with bndtools !
So, regarding the current issue I'm trying to report, I could not reproduce
it so far in DEBUG mode. But while travelling to vacation, I managed to log
to a file in /tmp asynchronously instead of logging to the BndTools console
and I finally reproduced the issue with DEBUG !
Since this log file is a bit large, I prefer to continue the investigation
on this issue using the FELIX-4984, where I will attach the log file.
Thanks for your patience !
/Pierre
On Wed, Aug 5, 2015 at 6:05 AM, David Jencks <da...@gmail.com>
wrote:
> Hi Pierre,
>
> After switching all the projects to java 7 I was able to get eclipse to
> build ds and ds.itests and run the tests inside eclipse. But, even after
> 20 or 30 runs it always passes for me.
>
> It looks to me like the logging is not actually showing any of the debug
> level messages from the ds runtime that I expect. Do you have any idea why
> not? There isn’t nearly enough information in the logs below for me to
> analyze what/s going on.
>
> Since I don’t seem to be able to reproduce the problem would you like to
> mention what you think the cause is?
>
> I sure like the bndtools environment better!! I can’t wait till we get ds
> itself converted!
>
> thanks
> david jencks
>
>
>
> > On Aug 1, 2015, at 5:57 PM, Pierre De Rop <pi...@gmail.com>
> wrote:
> >
> > 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 <pi...@gmail.com>
> > 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 <
> >> 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 <pi...@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 <pi...@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
> >>>>>
> >>>>>
> >>>
> >>>
> >>
>
>
>
Re: [SCR] issue in CircularReferenceTest ?
Posted by David Jencks <da...@gmail.com>.
Hi Pierre,
After switching all the projects to java 7 I was able to get eclipse to build ds and ds.itests and run the tests inside eclipse. But, even after 20 or 30 runs it always passes for me.
It looks to me like the logging is not actually showing any of the debug level messages from the ds runtime that I expect. Do you have any idea why not? There isn’t nearly enough information in the logs below for me to analyze what/s going on.
Since I don’t seem to be able to reproduce the problem would you like to mention what you think the cause is?
I sure like the bndtools environment better!! I can’t wait till we get ds itself converted!
thanks
david jencks
> On Aug 1, 2015, at 5:57 PM, Pierre De Rop <pi...@gmail.com> wrote:
>
> 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 <pi...@gmail.com>
> 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 <
>> 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 <pi...@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 <pi...@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
>>>>>
>>>>>
>>>
>>>
>>
Re: [SCR] issue in CircularReferenceTest ?
Posted by Pierre De Rop <pi...@gmail.com>.
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 <pi...@gmail.com>
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 <
> 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 <pi...@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 <pi...@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
>> >>
>> >>
>>
>>
>
Re: [SCR] issue in CircularReferenceTest ?
Posted by Pierre De Rop <pi...@gmail.com>.
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 <pi...@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 <da...@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 <pi...@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
> >>
> >>
>
>