You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@karaf.apache.org by Mike Wilson <mi...@hotmail.com> on 2014/09/10 18:09:58 UTC

startup failures

We're having intermittent startup problems on Karaf 2.3.0 and I'd just want
to check with you here how I can investigate this further. What we see is
that sometimes all bundles won't start correctly. I've been digging through
a number of log files and a typical case seems to be that central bundles
get stuck in GracePeriod and this will in turn affect other bundles. 
 
Here's an excerpt of one of the logs where you can see that two
karaf.features bundles end up in GracePeriod:
 
2014-09-04 21:44:54,878  BundleEvent.STARTED
org.apache.aries.proxy.impl
2014-09-04 21:44:54,905  BundleEvent.RESOLVED
org.apache.aries.blueprint.cm
2014-09-04 21:44:54,933  BundleEvent.STARTED
org.apache.aries.blueprint.cm
2014-09-04 21:44:54,937  BlueprintEvent.CREATING
org.apache.aries.blueprint.cm
2014-09-04 21:44:55,081  BlueprintEvent.CREATING
org.apache.karaf.features.core
2014-09-04 21:44:55,100  BlueprintEvent.GRACE_PERIOD
org.apache.karaf.features.core
2014-09-04 21:44:55,122  BlueprintEvent.CREATED
org.apache.aries.blueprint.cm
2014-09-04 21:44:55,123  BlueprintEvent.CREATED
org.apache.aries.blueprint.core
2014-09-04 21:44:55,260  BundleEvent.RESOLVED
org.apache.aries.jmx.api
2014-09-04 21:44:55,260  BundleEvent.RESOLVED
org.apache.aries.jmx.core
2014-09-04 21:44:55,492  BundleEvent.STARTED
org.apache.aries.jmx.api
2014-09-04 21:44:55,492  BundleEvent.STARTED
org.apache.aries.jmx.core
2014-09-04 21:44:55,525  BundleEvent.RESOLVED
org.apache.aries.jmx.blueprint.api
2014-09-04 21:44:55,526  BundleEvent.STARTED
org.apache.aries.jmx.blueprint.api
2014-09-04 21:44:55,560  BundleEvent.RESOLVED
org.apache.aries.jmx.blueprint.core
2014-09-04 21:44:55,575  BundleEvent.STARTED
org.apache.aries.jmx.blueprint.core
2014-09-04 21:44:55,873  BlueprintEvent.CREATING
org.apache.karaf.features.command
2014-09-04 21:44:55,939  BlueprintEvent.GRACE_PERIOD
org.apache.karaf.features.command
2014-09-04 21:44:56,878  BlueprintEvent.CREATING
org.apache.karaf.deployer.features
2014-09-04 21:44:56,905  BlueprintEvent.CREATED
org.apache.karaf.deployer.features

The first one is waiting for
namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ext/v1.0.0:
 
2014-09-04 21:44:55,100 | DEBUG | rint Extender: 3 |  |  |
ntainer.BlueprintEventDispatcher  136 | 7 - org.apache.aries.blueprint.core
- 1.0.1 | Sending blueprint container event
BlueprintEvent[type=GRACE_PERIOD,
dependencies=[(&(objectClass=org.apache.aries.blueprint.NamespaceHandler)(os
gi.service.blueprint.namespace=http://aries.apache.org/blueprint/xmlns/bluep
rint-ext/v1.0.0))]] for bundle org.apache.karaf.features.core

which I thought should be successfully registered as
org.apache.aries.blueprint.core had BlueprintEvent.CREATED.
 
Does this make sense? What else could I look at to understand the issue?
This is in a production system so I would like to investigate as much as
possible before taking the step to upgrade versions of Karaf etc (this is
scheduled for a later project).
 
Thanks
Mike

RE: startup failures

Posted by Mike Wilson <mi...@hotmail.com>.
Based on your info JB I now found the related tickets. Our problems seem to
match exactly what is described in:
  https://issues.apache.org/jira/browse/ARIES-944
and that you workaround in Karaf with:
  org.apache.aries.blueprint.synchronous=true
according to:
  https://issues.apache.org/jira/browse/KARAF-1925

So yeah, it seems Aries Blueprint doesn't work reliably in the default
asynchronous initialization mode. With this info I have enough to get a
version upgrade done in production so will go that route.

Thanks
Mike

> -----Original Message-----
> From: Mike Wilson [mailto:mikewse@hotmail.com] 
> Sent: den 10 september 2014 20:48
> To: user@karaf.apache.org
> Subject: RE: startup failures
> 
> As I wrote earlier it is not easy for me to upgrade versions 
> on a hunch but
> I'll see what I can do.
> 
> But thinking again I find it strange that Blueprint initialization of
> org.apache.karaf.features.core is started before Blueprint 
> initialization of
> org.apache.aries.blueprint.core, as I guess the latter is 
> what implements
> the Blueprint container? :-P
> 
> Best regards
> Mike
> 
> Jean-Baptiste Onofré wrote:
> > Oh ok.
> > 
> > We improved Karaf feature and bundle start level support in 
> > Karaf 2.3.3. 
> > Can you try with latest Karaf version (2.3.6) ?
> > 
> > Regards
> > JB
> > 
> > On 09/10/2014 08:18 PM, Mike Wilson wrote:
> > > Thanks for your response, Jean-Baptiste,
> > >
> > > I'd just like to clarify that I don't consider these "my" 
> > bundles :-) but
> > > rather part of Karaf.
> > > Looking at etc/startup.properties I find:
> > >
> > > 
> > org/apache/aries/blueprint/org.apache.aries.blueprint.core/1.0
> > .1/org.apache.
> > > aries.blueprint.core-1.0.1.jar=20
> > > ...
> > > 
> > org/apache/karaf/features/org.apache.karaf.features.core/2.3.0
> > /org.apache.ka
> > > raf.features.core-2.3.0.jar=25
> > >
> > > and in other files we have configured our own bundles to 
> > start at levels
> > > 35-100.
> > >
> > > If you look at the event list from my previous mail you can 
> > see that the
> > > bundle start order is analogous with the above. But, the 
> > asynchronous
> > > Blueprint initialization takes place in the opposite order 
> > (which is legal
> > > for asynchronous activities):
> > >
> > > 2014-09-04 21:44:55,081  BlueprintEvent.CREATING
> > > org.apache.karaf.features.core
> > > 2014-09-04 21:44:55,100  BlueprintEvent.GRACE_PERIOD
> > > org.apache.karaf.features.core
> > > ...
> > > 2014-09-04 21:44:55,123  BlueprintEvent.CREATED
> > > org.apache.aries.blueprint.core
> > >
> > > Normally I would expect org.apache.karaf.features.core to 
> > "wake up" from its
> > > waiting in GracePeriod once 
> org.apache.aries.blueprint.core has been
> > > initialized but this doesn't seem to happen. So,
> > > - are there any known bugs in this area?
> > > - or, isn't the blueprint-ext namespace actually registered by
> > >    org.apache.aries.blueprint.core?
> > > - or, is something completely different causing this problem?
> > >
> > > Thanks :)
> > > Mike
> > >
> > > Jean-Baptiste Onofré wrote:
> > >> Hi Mike,
> > >>
> > >> it looks like your bundles start before some other.
> > >>
> > >> Do you tune the bundles start level ?
> > >>
> > >> The GracePeriod means that the blueprint bundle is waiting
> > >> for services
> > >> not yet there.
> > >>
> > >> Regards
> > >> JB
> > >>
> > >> On 09/10/2014 06:09 PM, Mike Wilson wrote:
> > >>> We're having intermittent startup problems on Karaf 2.3.0
> > >> and I'd just
> > >>> want to check with you here how I can investigate this
> > >> further. What we
> > >>> see is that sometimes all bundles won't start 
> correctly. I've been
> > >>> digging through a number of log files and a typical case 
> > seems to be
> > >>> that central bundles get stuck in GracePeriod and this 
> > will in turn
> > >>> affect other bundles.
> > >>> Here's an excerpt of one of the logs where you can see that two
> > >>> karaf.features bundles end up in GracePeriod:
> > >>> 2014-09-04 21:44:54,878 BundleEvent.STARTED
> > >> org.apache.aries.proxy.impl
> > >>> 2014-09-04 21:44:54,905 BundleEvent.RESOLVED
> > >> org.apache.aries.blueprint.cm
> > >>> 2014-09-04 21:44:54,933 BundleEvent.STARTED
> > >> org.apache.aries.blueprint.cm
> > >>> 2014-09-04 21:44:54,937 BlueprintEvent.CREATING
> > >>> org.apache.aries.blueprint.cm
> > >>> 2014-09-04 21:44:55,081 BlueprintEvent.CREATING
> > >>> org.apache.karaf.features.core
> > >>> 2014-09-04 21:44:55,100 BlueprintEvent.GRACE_PERIOD
> > >>> org.apache.karaf.features.core
> > >>> 2014-09-04 21:44:55,122 BlueprintEvent.CREATED
> > >> org.apache.aries.blueprint.cm
> > >>> 2014-09-04 21:44:55,123 BlueprintEvent.CREATED
> > >>> org.apache.aries.blueprint.core
> > >>> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED
> > >> org.apache.aries.jmx.api
> > >>> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED
> > >> org.apache.aries.jmx.core
> > >>> 2014-09-04 21:44:55,492 BundleEvent.STARTED 
> > org.apache.aries.jmx.api
> > >>> 2014-09-04 21:44:55,492 BundleEvent.STARTED
> > >> org.apache.aries.jmx.core
> > >>> 2014-09-04 21:44:55,525 BundleEvent.RESOLVED
> > >>> org.apache.aries.jmx.blueprint.api
> > >>> 2014-09-04 21:44:55,526 BundleEvent.STARTED
> > >>> org.apache.aries.jmx.blueprint.api
> > >>> 2014-09-04 21:44:55,560 BundleEvent.RESOLVED
> > >>> org.apache.aries.jmx.blueprint.core
> > >>> 2014-09-04 21:44:55,575 BundleEvent.STARTED
> > >>> org.apache.aries.jmx.blueprint.core
> > >>> 2014-09-04 21:44:55,873 BlueprintEvent.CREATING
> > >>> org.apache.karaf.features.command
> > >>> 2014-09-04 21:44:55,939 BlueprintEvent.GRACE_PERIOD
> > >>> org.apache.karaf.features.command
> > >>> 2014-09-04 21:44:56,878 BlueprintEvent.CREATING
> > >>> org.apache.karaf.deployer.features
> > >>> 2014-09-04 21:44:56,905 BlueprintEvent.CREATED
> > >>> org.apache.karaf.deployer.features
> > >>> The first one is waiting for
> > >>>
> > >> namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ex
> > >> t/v1.0.0:
> > >>> 2014-09-04 21:44:55,100 | DEBUG | rint Extender: 3 |  |  |
> > >>> ntainer.BlueprintEventDispatcher  136 | 7 -
> > >>> org.apache.aries.blueprint.core - 1.0.1 | Sending blueprint
> > >> container
> > >>> event BlueprintEvent[type=GRACE_PERIOD,
> > >>>
> > >> dependencies=[(&(objectClass=org.apache.aries.blueprint.Namesp
> > >> aceHandler)(osgi.service.blueprint.namespace=http://aries.apac
> > >> he.org/blueprint/xmlns/blueprint-ext/v1.0.0))]]
> > >>> for bundle org.apache.karaf.features.core
> > >>> which I thought should be successfully registered as
> > >>> org.apache.aries.blueprint.core had BlueprintEvent.CREATED.
> > >>> Does this make sense? What else could I look at to
> > >> understand the issue?
> > >>> This is in a production system so I would like to
> > >> investigate as much as
> > >>> possible before taking the step to upgrade versions of
> > >> Karaf etc (this
> > >>> is scheduled for a later project).
> > >>> Thanks
> > >>> Mike
> > >>
> > >> --
> > >> Jean-Baptiste Onofré
> > >> jbonofre@apache.org
> > >> http://blog.nanthrax.net
> > >> Talend - http://www.talend.com
> > >>
> > >
> > 
> > -- 
> > Jean-Baptiste Onofré
> > jbonofre@apache.org
> > http://blog.nanthrax.net
> > Talend - http://www.talend.com
> > 
> 
> 


RE: startup failures

Posted by Mike Wilson <mi...@hotmail.com>.
As I wrote earlier it is not easy for me to upgrade versions on a hunch but
I'll see what I can do.

But thinking again I find it strange that Blueprint initialization of
org.apache.karaf.features.core is started before Blueprint initialization of
org.apache.aries.blueprint.core, as I guess the latter is what implements
the Blueprint container? :-P

Best regards
Mike

Jean-Baptiste Onofré wrote:
> Oh ok.
> 
> We improved Karaf feature and bundle start level support in 
> Karaf 2.3.3. 
> Can you try with latest Karaf version (2.3.6) ?
> 
> Regards
> JB
> 
> On 09/10/2014 08:18 PM, Mike Wilson wrote:
> > Thanks for your response, Jean-Baptiste,
> >
> > I'd just like to clarify that I don't consider these "my" 
> bundles :-) but
> > rather part of Karaf.
> > Looking at etc/startup.properties I find:
> >
> > 
> org/apache/aries/blueprint/org.apache.aries.blueprint.core/1.0
> .1/org.apache.
> > aries.blueprint.core-1.0.1.jar=20
> > ...
> > 
> org/apache/karaf/features/org.apache.karaf.features.core/2.3.0
> /org.apache.ka
> > raf.features.core-2.3.0.jar=25
> >
> > and in other files we have configured our own bundles to 
> start at levels
> > 35-100.
> >
> > If you look at the event list from my previous mail you can 
> see that the
> > bundle start order is analogous with the above. But, the 
> asynchronous
> > Blueprint initialization takes place in the opposite order 
> (which is legal
> > for asynchronous activities):
> >
> > 2014-09-04 21:44:55,081  BlueprintEvent.CREATING
> > org.apache.karaf.features.core
> > 2014-09-04 21:44:55,100  BlueprintEvent.GRACE_PERIOD
> > org.apache.karaf.features.core
> > ...
> > 2014-09-04 21:44:55,123  BlueprintEvent.CREATED
> > org.apache.aries.blueprint.core
> >
> > Normally I would expect org.apache.karaf.features.core to 
> "wake up" from its
> > waiting in GracePeriod once org.apache.aries.blueprint.core has been
> > initialized but this doesn't seem to happen. So,
> > - are there any known bugs in this area?
> > - or, isn't the blueprint-ext namespace actually registered by
> >    org.apache.aries.blueprint.core?
> > - or, is something completely different causing this problem?
> >
> > Thanks :)
> > Mike
> >
> > Jean-Baptiste Onofré wrote:
> >> Hi Mike,
> >>
> >> it looks like your bundles start before some other.
> >>
> >> Do you tune the bundles start level ?
> >>
> >> The GracePeriod means that the blueprint bundle is waiting
> >> for services
> >> not yet there.
> >>
> >> Regards
> >> JB
> >>
> >> On 09/10/2014 06:09 PM, Mike Wilson wrote:
> >>> We're having intermittent startup problems on Karaf 2.3.0
> >> and I'd just
> >>> want to check with you here how I can investigate this
> >> further. What we
> >>> see is that sometimes all bundles won't start correctly. I've been
> >>> digging through a number of log files and a typical case 
> seems to be
> >>> that central bundles get stuck in GracePeriod and this 
> will in turn
> >>> affect other bundles.
> >>> Here's an excerpt of one of the logs where you can see that two
> >>> karaf.features bundles end up in GracePeriod:
> >>> 2014-09-04 21:44:54,878 BundleEvent.STARTED
> >> org.apache.aries.proxy.impl
> >>> 2014-09-04 21:44:54,905 BundleEvent.RESOLVED
> >> org.apache.aries.blueprint.cm
> >>> 2014-09-04 21:44:54,933 BundleEvent.STARTED
> >> org.apache.aries.blueprint.cm
> >>> 2014-09-04 21:44:54,937 BlueprintEvent.CREATING
> >>> org.apache.aries.blueprint.cm
> >>> 2014-09-04 21:44:55,081 BlueprintEvent.CREATING
> >>> org.apache.karaf.features.core
> >>> 2014-09-04 21:44:55,100 BlueprintEvent.GRACE_PERIOD
> >>> org.apache.karaf.features.core
> >>> 2014-09-04 21:44:55,122 BlueprintEvent.CREATED
> >> org.apache.aries.blueprint.cm
> >>> 2014-09-04 21:44:55,123 BlueprintEvent.CREATED
> >>> org.apache.aries.blueprint.core
> >>> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED
> >> org.apache.aries.jmx.api
> >>> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED
> >> org.apache.aries.jmx.core
> >>> 2014-09-04 21:44:55,492 BundleEvent.STARTED 
> org.apache.aries.jmx.api
> >>> 2014-09-04 21:44:55,492 BundleEvent.STARTED
> >> org.apache.aries.jmx.core
> >>> 2014-09-04 21:44:55,525 BundleEvent.RESOLVED
> >>> org.apache.aries.jmx.blueprint.api
> >>> 2014-09-04 21:44:55,526 BundleEvent.STARTED
> >>> org.apache.aries.jmx.blueprint.api
> >>> 2014-09-04 21:44:55,560 BundleEvent.RESOLVED
> >>> org.apache.aries.jmx.blueprint.core
> >>> 2014-09-04 21:44:55,575 BundleEvent.STARTED
> >>> org.apache.aries.jmx.blueprint.core
> >>> 2014-09-04 21:44:55,873 BlueprintEvent.CREATING
> >>> org.apache.karaf.features.command
> >>> 2014-09-04 21:44:55,939 BlueprintEvent.GRACE_PERIOD
> >>> org.apache.karaf.features.command
> >>> 2014-09-04 21:44:56,878 BlueprintEvent.CREATING
> >>> org.apache.karaf.deployer.features
> >>> 2014-09-04 21:44:56,905 BlueprintEvent.CREATED
> >>> org.apache.karaf.deployer.features
> >>> The first one is waiting for
> >>>
> >> namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ex
> >> t/v1.0.0:
> >>> 2014-09-04 21:44:55,100 | DEBUG | rint Extender: 3 |  |  |
> >>> ntainer.BlueprintEventDispatcher  136 | 7 -
> >>> org.apache.aries.blueprint.core - 1.0.1 | Sending blueprint
> >> container
> >>> event BlueprintEvent[type=GRACE_PERIOD,
> >>>
> >> dependencies=[(&(objectClass=org.apache.aries.blueprint.Namesp
> >> aceHandler)(osgi.service.blueprint.namespace=http://aries.apac
> >> he.org/blueprint/xmlns/blueprint-ext/v1.0.0))]]
> >>> for bundle org.apache.karaf.features.core
> >>> which I thought should be successfully registered as
> >>> org.apache.aries.blueprint.core had BlueprintEvent.CREATED.
> >>> Does this make sense? What else could I look at to
> >> understand the issue?
> >>> This is in a production system so I would like to
> >> investigate as much as
> >>> possible before taking the step to upgrade versions of
> >> Karaf etc (this
> >>> is scheduled for a later project).
> >>> Thanks
> >>> Mike
> >>
> >> --
> >> Jean-Baptiste Onofré
> >> jbonofre@apache.org
> >> http://blog.nanthrax.net
> >> Talend - http://www.talend.com
> >>
> >
> 
> -- 
> Jean-Baptiste Onofré
> jbonofre@apache.org
> http://blog.nanthrax.net
> Talend - http://www.talend.com
> 


Re: startup failures

Posted by Jean-Baptiste Onofré <jb...@nanthrax.net>.
Oh ok.

We improved Karaf feature and bundle start level support in Karaf 2.3.3. 
Can you try with latest Karaf version (2.3.6) ?

Regards
JB

On 09/10/2014 08:18 PM, Mike Wilson wrote:
> Thanks for your response, Jean-Baptiste,
>
> I'd just like to clarify that I don't consider these "my" bundles :-) but
> rather part of Karaf.
> Looking at etc/startup.properties I find:
>
> org/apache/aries/blueprint/org.apache.aries.blueprint.core/1.0.1/org.apache.
> aries.blueprint.core-1.0.1.jar=20
> ...
> org/apache/karaf/features/org.apache.karaf.features.core/2.3.0/org.apache.ka
> raf.features.core-2.3.0.jar=25
>
> and in other files we have configured our own bundles to start at levels
> 35-100.
>
> If you look at the event list from my previous mail you can see that the
> bundle start order is analogous with the above. But, the asynchronous
> Blueprint initialization takes place in the opposite order (which is legal
> for asynchronous activities):
>
> 2014-09-04 21:44:55,081  BlueprintEvent.CREATING
> org.apache.karaf.features.core
> 2014-09-04 21:44:55,100  BlueprintEvent.GRACE_PERIOD
> org.apache.karaf.features.core
> ...
> 2014-09-04 21:44:55,123  BlueprintEvent.CREATED
> org.apache.aries.blueprint.core
>
> Normally I would expect org.apache.karaf.features.core to "wake up" from its
> waiting in GracePeriod once org.apache.aries.blueprint.core has been
> initialized but this doesn't seem to happen. So,
> - are there any known bugs in this area?
> - or, isn't the blueprint-ext namespace actually registered by
>    org.apache.aries.blueprint.core?
> - or, is something completely different causing this problem?
>
> Thanks :)
> Mike
>
> Jean-Baptiste Onofré wrote:
>> Hi Mike,
>>
>> it looks like your bundles start before some other.
>>
>> Do you tune the bundles start level ?
>>
>> The GracePeriod means that the blueprint bundle is waiting
>> for services
>> not yet there.
>>
>> Regards
>> JB
>>
>> On 09/10/2014 06:09 PM, Mike Wilson wrote:
>>> We're having intermittent startup problems on Karaf 2.3.0
>> and I'd just
>>> want to check with you here how I can investigate this
>> further. What we
>>> see is that sometimes all bundles won't start correctly. I've been
>>> digging through a number of log files and a typical case seems to be
>>> that central bundles get stuck in GracePeriod and this will in turn
>>> affect other bundles.
>>> Here's an excerpt of one of the logs where you can see that two
>>> karaf.features bundles end up in GracePeriod:
>>> 2014-09-04 21:44:54,878 BundleEvent.STARTED
>> org.apache.aries.proxy.impl
>>> 2014-09-04 21:44:54,905 BundleEvent.RESOLVED
>> org.apache.aries.blueprint.cm
>>> 2014-09-04 21:44:54,933 BundleEvent.STARTED
>> org.apache.aries.blueprint.cm
>>> 2014-09-04 21:44:54,937 BlueprintEvent.CREATING
>>> org.apache.aries.blueprint.cm
>>> 2014-09-04 21:44:55,081 BlueprintEvent.CREATING
>>> org.apache.karaf.features.core
>>> 2014-09-04 21:44:55,100 BlueprintEvent.GRACE_PERIOD
>>> org.apache.karaf.features.core
>>> 2014-09-04 21:44:55,122 BlueprintEvent.CREATED
>> org.apache.aries.blueprint.cm
>>> 2014-09-04 21:44:55,123 BlueprintEvent.CREATED
>>> org.apache.aries.blueprint.core
>>> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED
>> org.apache.aries.jmx.api
>>> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED
>> org.apache.aries.jmx.core
>>> 2014-09-04 21:44:55,492 BundleEvent.STARTED org.apache.aries.jmx.api
>>> 2014-09-04 21:44:55,492 BundleEvent.STARTED
>> org.apache.aries.jmx.core
>>> 2014-09-04 21:44:55,525 BundleEvent.RESOLVED
>>> org.apache.aries.jmx.blueprint.api
>>> 2014-09-04 21:44:55,526 BundleEvent.STARTED
>>> org.apache.aries.jmx.blueprint.api
>>> 2014-09-04 21:44:55,560 BundleEvent.RESOLVED
>>> org.apache.aries.jmx.blueprint.core
>>> 2014-09-04 21:44:55,575 BundleEvent.STARTED
>>> org.apache.aries.jmx.blueprint.core
>>> 2014-09-04 21:44:55,873 BlueprintEvent.CREATING
>>> org.apache.karaf.features.command
>>> 2014-09-04 21:44:55,939 BlueprintEvent.GRACE_PERIOD
>>> org.apache.karaf.features.command
>>> 2014-09-04 21:44:56,878 BlueprintEvent.CREATING
>>> org.apache.karaf.deployer.features
>>> 2014-09-04 21:44:56,905 BlueprintEvent.CREATED
>>> org.apache.karaf.deployer.features
>>> The first one is waiting for
>>>
>> namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ex
>> t/v1.0.0:
>>> 2014-09-04 21:44:55,100 | DEBUG | rint Extender: 3 |  |  |
>>> ntainer.BlueprintEventDispatcher  136 | 7 -
>>> org.apache.aries.blueprint.core - 1.0.1 | Sending blueprint
>> container
>>> event BlueprintEvent[type=GRACE_PERIOD,
>>>
>> dependencies=[(&(objectClass=org.apache.aries.blueprint.Namesp
>> aceHandler)(osgi.service.blueprint.namespace=http://aries.apac
>> he.org/blueprint/xmlns/blueprint-ext/v1.0.0))]]
>>> for bundle org.apache.karaf.features.core
>>> which I thought should be successfully registered as
>>> org.apache.aries.blueprint.core had BlueprintEvent.CREATED.
>>> Does this make sense? What else could I look at to
>> understand the issue?
>>> This is in a production system so I would like to
>> investigate as much as
>>> possible before taking the step to upgrade versions of
>> Karaf etc (this
>>> is scheduled for a later project).
>>> Thanks
>>> Mike
>>
>> --
>> Jean-Baptiste Onofré
>> jbonofre@apache.org
>> http://blog.nanthrax.net
>> Talend - http://www.talend.com
>>
>

-- 
Jean-Baptiste Onofré
jbonofre@apache.org
http://blog.nanthrax.net
Talend - http://www.talend.com

RE: startup failures

Posted by Mike Wilson <mi...@hotmail.com>.
Thanks for your response, Jean-Baptiste,

I'd just like to clarify that I don't consider these "my" bundles :-) but
rather part of Karaf.
Looking at etc/startup.properties I find:

org/apache/aries/blueprint/org.apache.aries.blueprint.core/1.0.1/org.apache.
aries.blueprint.core-1.0.1.jar=20
...
org/apache/karaf/features/org.apache.karaf.features.core/2.3.0/org.apache.ka
raf.features.core-2.3.0.jar=25

and in other files we have configured our own bundles to start at levels
35-100.

If you look at the event list from my previous mail you can see that the
bundle start order is analogous with the above. But, the asynchronous
Blueprint initialization takes place in the opposite order (which is legal
for asynchronous activities):

2014-09-04 21:44:55,081  BlueprintEvent.CREATING
org.apache.karaf.features.core
2014-09-04 21:44:55,100  BlueprintEvent.GRACE_PERIOD
org.apache.karaf.features.core
...
2014-09-04 21:44:55,123  BlueprintEvent.CREATED
org.apache.aries.blueprint.core

Normally I would expect org.apache.karaf.features.core to "wake up" from its
waiting in GracePeriod once org.apache.aries.blueprint.core has been
initialized but this doesn't seem to happen. So,
- are there any known bugs in this area?
- or, isn't the blueprint-ext namespace actually registered by 
  org.apache.aries.blueprint.core?
- or, is something completely different causing this problem?

Thanks :)
Mike

Jean-Baptiste Onofré wrote:
> Hi Mike,
> 
> it looks like your bundles start before some other.
> 
> Do you tune the bundles start level ?
> 
> The GracePeriod means that the blueprint bundle is waiting 
> for services 
> not yet there.
> 
> Regards
> JB
> 
> On 09/10/2014 06:09 PM, Mike Wilson wrote:
> > We're having intermittent startup problems on Karaf 2.3.0 
> and I'd just
> > want to check with you here how I can investigate this 
> further. What we
> > see is that sometimes all bundles won't start correctly. I've been
> > digging through a number of log files and a typical case seems to be
> > that central bundles get stuck in GracePeriod and this will in turn
> > affect other bundles.
> > Here's an excerpt of one of the logs where you can see that two
> > karaf.features bundles end up in GracePeriod:
> > 2014-09-04 21:44:54,878 BundleEvent.STARTED 
> org.apache.aries.proxy.impl
> > 2014-09-04 21:44:54,905 BundleEvent.RESOLVED 
> org.apache.aries.blueprint.cm
> > 2014-09-04 21:44:54,933 BundleEvent.STARTED 
> org.apache.aries.blueprint.cm
> > 2014-09-04 21:44:54,937 BlueprintEvent.CREATING
> > org.apache.aries.blueprint.cm
> > 2014-09-04 21:44:55,081 BlueprintEvent.CREATING
> > org.apache.karaf.features.core
> > 2014-09-04 21:44:55,100 BlueprintEvent.GRACE_PERIOD
> > org.apache.karaf.features.core
> > 2014-09-04 21:44:55,122 BlueprintEvent.CREATED 
> org.apache.aries.blueprint.cm
> > 2014-09-04 21:44:55,123 BlueprintEvent.CREATED
> > org.apache.aries.blueprint.core
> > 2014-09-04 21:44:55,260 BundleEvent.RESOLVED 
> org.apache.aries.jmx.api
> > 2014-09-04 21:44:55,260 BundleEvent.RESOLVED 
> org.apache.aries.jmx.core
> > 2014-09-04 21:44:55,492 BundleEvent.STARTED org.apache.aries.jmx.api
> > 2014-09-04 21:44:55,492 BundleEvent.STARTED 
> org.apache.aries.jmx.core
> > 2014-09-04 21:44:55,525 BundleEvent.RESOLVED
> > org.apache.aries.jmx.blueprint.api
> > 2014-09-04 21:44:55,526 BundleEvent.STARTED
> > org.apache.aries.jmx.blueprint.api
> > 2014-09-04 21:44:55,560 BundleEvent.RESOLVED
> > org.apache.aries.jmx.blueprint.core
> > 2014-09-04 21:44:55,575 BundleEvent.STARTED
> > org.apache.aries.jmx.blueprint.core
> > 2014-09-04 21:44:55,873 BlueprintEvent.CREATING
> > org.apache.karaf.features.command
> > 2014-09-04 21:44:55,939 BlueprintEvent.GRACE_PERIOD
> > org.apache.karaf.features.command
> > 2014-09-04 21:44:56,878 BlueprintEvent.CREATING
> > org.apache.karaf.deployer.features
> > 2014-09-04 21:44:56,905 BlueprintEvent.CREATED
> > org.apache.karaf.deployer.features
> > The first one is waiting for
> > 
> namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ex
> t/v1.0.0:
> > 2014-09-04 21:44:55,100 | DEBUG | rint Extender: 3 |  |  |
> > ntainer.BlueprintEventDispatcher  136 | 7 -
> > org.apache.aries.blueprint.core - 1.0.1 | Sending blueprint 
> container
> > event BlueprintEvent[type=GRACE_PERIOD,
> > 
> dependencies=[(&(objectClass=org.apache.aries.blueprint.Namesp
> aceHandler)(osgi.service.blueprint.namespace=http://aries.apac
> he.org/blueprint/xmlns/blueprint-ext/v1.0.0))]]
> > for bundle org.apache.karaf.features.core
> > which I thought should be successfully registered as
> > org.apache.aries.blueprint.core had BlueprintEvent.CREATED.
> > Does this make sense? What else could I look at to 
> understand the issue?
> > This is in a production system so I would like to 
> investigate as much as
> > possible before taking the step to upgrade versions of 
> Karaf etc (this
> > is scheduled for a later project).
> > Thanks
> > Mike
> 
> -- 
> Jean-Baptiste Onofré
> jbonofre@apache.org
> http://blog.nanthrax.net
> Talend - http://www.talend.com
> 


Re: startup failures

Posted by Jean-Baptiste Onofré <jb...@nanthrax.net>.
Hi Mike,

it looks like your bundles start before some other.

Do you tune the bundles start level ?

The GracePeriod means that the blueprint bundle is waiting for services 
not yet there.

Regards
JB

On 09/10/2014 06:09 PM, Mike Wilson wrote:
> We're having intermittent startup problems on Karaf 2.3.0 and I'd just
> want to check with you here how I can investigate this further. What we
> see is that sometimes all bundles won't start correctly. I've been
> digging through a number of log files and a typical case seems to be
> that central bundles get stuck in GracePeriod and this will in turn
> affect other bundles.
> Here's an excerpt of one of the logs where you can see that two
> karaf.features bundles end up in GracePeriod:
> 2014-09-04 21:44:54,878 BundleEvent.STARTED org.apache.aries.proxy.impl
> 2014-09-04 21:44:54,905 BundleEvent.RESOLVED org.apache.aries.blueprint.cm
> 2014-09-04 21:44:54,933 BundleEvent.STARTED org.apache.aries.blueprint.cm
> 2014-09-04 21:44:54,937 BlueprintEvent.CREATING
> org.apache.aries.blueprint.cm
> 2014-09-04 21:44:55,081 BlueprintEvent.CREATING
> org.apache.karaf.features.core
> 2014-09-04 21:44:55,100 BlueprintEvent.GRACE_PERIOD
> org.apache.karaf.features.core
> 2014-09-04 21:44:55,122 BlueprintEvent.CREATED org.apache.aries.blueprint.cm
> 2014-09-04 21:44:55,123 BlueprintEvent.CREATED
> org.apache.aries.blueprint.core
> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED org.apache.aries.jmx.api
> 2014-09-04 21:44:55,260 BundleEvent.RESOLVED org.apache.aries.jmx.core
> 2014-09-04 21:44:55,492 BundleEvent.STARTED org.apache.aries.jmx.api
> 2014-09-04 21:44:55,492 BundleEvent.STARTED org.apache.aries.jmx.core
> 2014-09-04 21:44:55,525 BundleEvent.RESOLVED
> org.apache.aries.jmx.blueprint.api
> 2014-09-04 21:44:55,526 BundleEvent.STARTED
> org.apache.aries.jmx.blueprint.api
> 2014-09-04 21:44:55,560 BundleEvent.RESOLVED
> org.apache.aries.jmx.blueprint.core
> 2014-09-04 21:44:55,575 BundleEvent.STARTED
> org.apache.aries.jmx.blueprint.core
> 2014-09-04 21:44:55,873 BlueprintEvent.CREATING
> org.apache.karaf.features.command
> 2014-09-04 21:44:55,939 BlueprintEvent.GRACE_PERIOD
> org.apache.karaf.features.command
> 2014-09-04 21:44:56,878 BlueprintEvent.CREATING
> org.apache.karaf.deployer.features
> 2014-09-04 21:44:56,905 BlueprintEvent.CREATED
> org.apache.karaf.deployer.features
> The first one is waiting for
> namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ext/v1.0.0:
> 2014-09-04 21:44:55,100 | DEBUG | rint Extender: 3 |  |  |
> ntainer.BlueprintEventDispatcher  136 | 7 -
> org.apache.aries.blueprint.core - 1.0.1 | Sending blueprint container
> event BlueprintEvent[type=GRACE_PERIOD,
> dependencies=[(&(objectClass=org.apache.aries.blueprint.NamespaceHandler)(osgi.service.blueprint.namespace=http://aries.apache.org/blueprint/xmlns/blueprint-ext/v1.0.0))]]
> for bundle org.apache.karaf.features.core
> which I thought should be successfully registered as
> org.apache.aries.blueprint.core had BlueprintEvent.CREATED.
> Does this make sense? What else could I look at to understand the issue?
> This is in a production system so I would like to investigate as much as
> possible before taking the step to upgrade versions of Karaf etc (this
> is scheduled for a later project).
> Thanks
> Mike

-- 
Jean-Baptiste Onofré
jbonofre@apache.org
http://blog.nanthrax.net
Talend - http://www.talend.com