[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
RE: [equinox-dev] DS invocation order of bind and activate(timing issue???)

I think I've got a test case and test sequence to reproduce the timing problem. 

The problem arises from the start order of the bundles.

if the framework starts the bundles in the following order:

1) org.eclipse.osgi_3.4.0.v20080218
2) org.eclipse.equinox.ds_1.0.0.v20080218
3) org.eclipse.equinox.log_1.1.0.v20071203
4) org.eclipse.equinox.util_1.0.0.v20080218
5) javax.servlet_2.4.0.v200711021030
6) org.eclipse.osgi.services_3.1.200.v20071203
7) a_2.0.0
8) d_2.0.0

everything is OK (see attached running.txt), both services A and D get activated as expected.
Now, If i stop bundles 2-8 and start them in the following order (bundle 1 was not stopped):

2) javax.servlet_2.4.0.v200711021030
3) org.eclipse.equinox.ds_1.0.0.v20080218
4) org.eclipse.equinox.log_1.1.0.v20071203
5) org.eclipse.osgi.services_3.1.200.v20071203
6) a_2.0.0
7) d_2.0.0
8) org.eclipse.equinox.util_1.0.0.v20080218

I get the timeouts in the SCR (see fail.txt).

I also attached the two bundles I used to debug the problem. The source code 
is located within the OSGI-INF/src.

Based on this observation I think the SCR gets confused and does not obey the 
activation/bind order as I reported before.

-----Original Message-----
From: equinox-dev-bounces@xxxxxxxxxxx on behalf of BJ Hargrave
Sent: Fri 22.02.2008 20:05
To: Equinox development mailing list
Subject: Re: [equinox-dev] DS invocation order of bind and activate(timing	issue???)
 
I think you should put this in a bug report against DS.
-- 

BJ Hargrave
Senior Technical Staff Member, IBM
OSGi Fellow and CTO of the OSGi Alliance
hargrave@xxxxxxxxxx

office: +1 386 848 1781
mobile: +1 386 848 3788




From:
"Foerster, Stefan" <Stefan.Foerster@xxxxxxxx>
To:
equinox-dev@xxxxxxxxxxx
Date:
2008-02-22 11:52
Subject:
[equinox-dev] DS invocation order of bind and activate (timing  issue???)



Hello,

I'm having three bundles providing three services using the declarative 
service (version 1.0.0.v20080218):

bundle A:
<component name="A1" immediate="true">
  <implementation class="A1"/>
  <service>
    <provide interface="IA"/>
  </service>
  <property name="service.pid"     value="A1"/>
  <property name="service.ranking" value="1000"/>
  <reference name="b" interface="IB" bind="setB" unbind="unsetB" 
cardinality="0..n" policy="dynamic"/>
  <reference name="c" interface="IC" bind="setC" unbind="unsetC" 
cardinality="0..1" policy="dynamic"/>
  <reference name="d" interface="ID" bind="setD" unbind="unsetD" 
cardinality="1..1"/>
  <reference name="e" interface="IE" bind="setE" unbind="unsetE" 
cardinality="0..n" policy="dynamic"/>
</component>

bundle B:
<component name="B1">
  <implementation class="B1"/>
  <service>
    <provide interface="IB"/>
  </service>
  <property name="service.pid"         value="B1"/>
  <property name="service.ranking"     value="1000"/>
  <reference name="a" interface="IA" bind="setA" unbind="unsetA" 
cardinality="1..1"/>
  <reference name="d" interface="ID" bind="setD" unbind="unsetD" 
cardinality="1..1"/>
</component>

bundle D:
<component name="D1">
  <implementation class="D1"/>
  <service>
    <provide interface="ID"/>
  </service>
  <property name="service.pid"         value="D1"/>
  <property name="service.ranking"     value="1000"/>
  <reference name="logger" interface="org.osgi.service.log.LogService" 
bind="setLog" unbind="unsetLog" cardinality="0..1" policy="dynamic"/>
</component>

Reading the OSGi DS spec I assume the only valid method invocation order 
(if the methods exists and are accessible) is:
1) D1.activate()                   -> some instanceD
2) A1.setD(instanceD)
3) A1.activate()                   -> some instanceA
4) B1.setA(instanceA) and B1.setD(instanceD) in any order
5) B1.activate()                   -> some instanceB
6) A1.setB(instanceB)

Sometimes, it happens that B1 is activated before!!! A1. and I get the 
following 
order of calls from the OSGi log (calls to setD() are not logged!):

==
1: >Debug [51] D1: activate() initial@reference:file:../../build/d1.jar/
2: >Info [51] ServiceEvent REGISTERED {service.id=29}
3: >Info [54] ServiceEvent REGISTERED {service.id=30}
4: >Info [37] ServiceEvent REGISTERED {service.id=31}
5: >Info [52] ServiceEvent REGISTERED {service.id=32}
6: >Info [53] ServiceEvent REGISTERED {service.id=33}
7: >Warn [4] ComponentReference.bind(): bind method setE is not 
accessible! initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
8: >Warn [4] ComponentReference.bind(): bind method setB is not 
accessible! initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
9: >Debug [51] B1: activate() initial@reference:file:../../build/d1.jar/
10:>Debug [51] A1: setB() initial@reference:file:../../build/d1.jar/
11:>Debug [51] A1: setB() A1 not yet activated!!! initial@reference:
file:../../build/d1.jar/
12:>Debug [51] A1: activate() initial@reference:file:../../build/d1.jar/
13:>Debug [51] E1: activate() initial@reference:file:../../build/d1.jar/
14:>Debug [51] A1: setE() initial@reference:file:../../build/d1.jar/
15:>Debug [51] B2: activate() initial@reference:file:../../build/d1.jar/
16:>Debug [51] A1: setB() initial@reference:file:../../build/d1.jar/
17:>Warn [4] ComponentReference.bind(): service reference already bound: 
{IB}={service.ranking=1000, service.pid=B1, component.name=B1, 
component.id=4, service.id=33} initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
==

Please observe line 11! I inserted the check for activation since else 
some internal data structures of A1 were not 
initialised and I had NullPointerExceptions.
Since I check for activation, all services are at least started.


I also have a run the whole thing with DS debugging enabled, interestingly 
no service is started at all:

==
>Info [6] Log created; Log Size=100; Log Threshold=4 initial@reference:
file:org.eclipse.equinox.log_1.1.0.v20071203.jar/
>Info [6] ServiceEvent REGISTERED {service.id=23}
>Info [6] ServiceEvent REGISTERED {service.id=24}
>Info [6] ServiceEvent REGISTERED {service.id=25}
>Info [6] BundleEvent STARTED initial@reference:
file:org.eclipse.equinox.log_1.1.0.v20071203.jar/
>Debug [5] bundleentry://7/OSGI-INF/Activator.xml initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Debug [5] [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Warn [5] [SCR - WorkThread] Timeout ocurred! Thread was blocked on 
processing [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Info [7] BundleEvent STARTED initial@reference:file:../../build/b1.jar/
>Info [8] BundleEvent STARTED initial@reference:
file:org.apache.commons.logging_1.0.4.v200711021015.jar/
>Info [11] BundleEvent STARTED initial@reference:
file:org.eclipse.osgi.services_3.1.200.v20071203.jar/
>Debug [5] bundleentry://12/OSGI-INF/Activator.xml initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Debug [5] [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Warn [5] [SCR - WorkThread] Timeout ocurred! Thread was blocked on 
processing [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Info [12] BundleEvent STARTED initial@reference:file:../../build/a1.jar/
>Debug [5] bundleentry://14/OSGI-INF/Activator.xml initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Debug [5] [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Warn [5] [SCR - WorkThread] Timeout ocurred! Thread was blocked on 
processing [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Info [14] BundleEvent STARTED initial@reference:file:../../build/b2.jar/
>Debug [5] bundleentry://15/OSGI-INF/Activator.xml initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Debug [5] [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Warn [5] [SCR - WorkThread] Timeout ocurred! Thread was blocked on 
processing [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Info [15] BundleEvent STARTED initial@reference:file:../../build/e1.jar/
>Debug [5] bundleentry://16/OSGI-INF/Activator.xml initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Debug [5] bundleentry://16/OSGI-INF/Command.xml initial@reference:
file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Debug [5] [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Warn [5] [SCR - WorkThread] Timeout ocurred! Thread was blocked on 
processing [QueuedJob] WorkPerformer: 
org.eclipse.equinox.internal.ds.SCRManager@656de49c; actionType 1 
initial@reference:file:org.eclipse.equinox.ds_1.0.0.v20080218.jar/
>Info [16] BundleEvent STARTED initial@reference:file:../../build/d1.jar/
>Debug [17] DEBUG 17  [0] 1 :  initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 1001 : 0 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 101 : 0 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 102 : 0 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 3001 : 0 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 2001 : 0 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 3 : 4 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Info [17] ServiceEvent REGISTERED {service.id=26}
>Debug [17] DEBUG 17  [0] 4 : 1 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 33 : 3 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Info [17] ServiceEvent REGISTERED {service.id=27}
>Debug [17] DEBUG 17  [0] 5 : 0 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Debug [17] DEBUG 17  [0] 16 : 8 initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Info [17] BundleEvent STARTED initial@reference:
file:org.eclipse.equinox.util_1.0.0.v20080218.jar/
>Info [0] FrameworkEvent STARTLEVEL CHANGED System Bundle
==

Is there something wrong with my understanding of the DS or is there a 
(timing related) issue
within the DS?

Yours sincerely

Stefan
_______________________________________________
equinox-dev mailing list
equinox-dev@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/equinox-dev


_______________________________________________
equinox-dev mailing list
equinox-dev@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/equinox-dev



<<application/ms-tnef>>