Skip to main content

[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???)

Hi,

the timeouts of the SCR are gone if I use the latest build of the ds 
(org.eclipse.equinox.ds_1.0.0.N20080224-0010.jar)

However, the other problem (B1 activated before A1) still exists.

I prepared two bundles b1 and b2 (attached to this mail). Using these bundles 
and having the following start order:

0	ACTIVE      org.eclipse.osgi_3.4.0.v20080218
2	ACTIVE      org.eclipse.equinox.log_1.1.0.v20071203
3	ACTIVE      org.eclipse.equinox.util_1.0.0.v20080218
5	ACTIVE      javax.servlet_2.4.0.v200711021030
6	ACTIVE      org.eclipse.osgi.services_3.1.200.v20071203
15	ACTIVE      org.eclipse.equinox.ds_1.0.0.N20080224-0010
21	ACTIVE      b1_2.0.0
22	ACTIVE      b2_2.0.0
23	ACTIVE      d_2.0.0
25	ACTIVE      a_2.0.0

of the framework. A1 is always used NOT activated!

I get the following output (via System.err.println()):
osgi> DEBUG: D: activate()
setD()
DEBUG: Activator: activate()
DEBUG: B2: startup()
A: setB() called while not activated !!!!!!
setD()
DEBUG: Activator: activate()
DEBUG: A: begin startup
DEBUG: A: finished startup
setD()
DEBUG: Activator: activate()
DEBUG: B1: startup()
DEBUG: A: setB()


-----Original Message-----
From: equinox-dev-bounces@xxxxxxxxxxx on behalf of O'Flynn, Dennis
Sent: Mon 25.02.2008 14:18
To: Equinox development mailing list
Subject: RE: [equinox-dev] DS invocation order of bind and activate(timingissue???)
 
Not sure if the following is related.  Maybe someone more familiar w/
equinox ds/util could comment on this.

1) equinox ds imports packages from util
2) equinox util is NOT lazy started

Q: Is equinox ds dependent upon service provide by equinox util that may
not be yet registered when ds is started before util?

If equinox util was lazy started, than I would assume that the 2nd
startup sequence listed below should have worked.


The contents of this e-mail are intended for the named addressee only. It contains information that may be confidential. Unless you are the named addressee or an authorized designee, you may not copy or use it, or disclose it to anyone else. If you received it in error please notify us immediately and then destroy it.

From: equinox-dev-bounces@xxxxxxxxxxx
[mailto:equinox-dev-bounces@xxxxxxxxxxx] On Behalf Of Foerster, Stefan
Sent: Monday, February 25, 2008 4:24 AM
To: Equinox development mailing list
Subject: 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
_______________________________________________
equinox-dev mailing list
equinox-dev@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/equinox-dev


<<application/ms-tnef>>


Back to the top