You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@felix.apache.org by Pierre De Rop <pi...@alcatel-lucent.fr> on 2008/09/07 23:06:29 UTC
SCR/ unexpected component reactivation while starting up JVM
Hi everyone;
I recently noticed a strange behaviour with Declarative Services.
Sometimes (rarely, but it happens), I see that my SCR components are
activated twice at jvm startup time.
Did anyone came across the same problem ?
I know that a component must expect to be deactivated/reactivated
(after a bundle update, or after a ConfigAdmin update for example),
But in my case, the problem occurs at startup (there is no bundle
update, and I don't use the ConfigAdmin service at all for my
components configurations).
I have the following components for our Alcatel-Lucent Distributed
Hashtable Service:
"ServiceLoader"
"DistributedSessions"
"Dht"
"DhtReg"
and in the following SCR log, around 23:59:39,066, you will see that
"DistributedSessions" component is deactivated/reactivated:
Here are the logs (please see my comments after the logs):
2008-09-06 23:59:39,012 FelixStartLevel DEBUG osgi - [ServiceLoader]
ManagerFactory.createManager
2008-09-06 23:59:39,019 FelixStartLevel DEBUG osgi - [ServiceLoader]
Component created
2008-09-06 23:59:39,037 SCR Component Actor DEBUG osgi -
[ServiceLoader] Enabling component
2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
[DistributedSessions] ManagerFactory.createManager
2008-09-06 23:59:39,038 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Disabled -> Enabled
2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
[DistributedSessions] Component created
2008-09-06 23:59:39,039 SCR Component Actor DEBUG osgi -
[ServiceLoader] Component enabled
2008-09-06 23:59:39,041 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Enabled -> Activating
2008-09-06 23:59:39,043 SCR Component Actor DEBUG osgi -
[ServiceLoader] Activating component
2008-09-06 23:59:39,047 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Activating -> Active
2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
[ServiceLoader] Component activated
2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
[DistributedSessions] Enabling component
2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
[DistributedSessions] State transition : Disabled -> Enabled
2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
[DistributedSessions] Component enabled
2008-09-06 23:59:39,049 FelixStartLevel DEBUG osgi - [Dht]
ManagerFactory.createManager
2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
[DistributedSessions] State transition : Enabled -> Activating
2008-09-06 23:59:39,050 SCR Component Actor DEBUG osgi -
[DistributedSessions] Activating component
2008-09-06 23:59:39,050 FelixStartLevel DEBUG osgi - [Dht] Component
created
2008-09-06 23:59:39,055 FelixStartLevel DEBUG osgi - [DhtSessionDir]
ManagerFactory.createManager
2008-09-06 23:59:39,058 FelixStartLevel DEBUG osgi - [DhtSessionDir]
Component created
2008-09-06 23:59:39,055 Configuration Updater DEBUG osgi -
[ServiceLoader] Deactivating and Activating to reconfigure from
configuration
2008-09-06 23:59:39,061 SCR Component Actor DEBUG osgi -
[DistributedSessions] State transition : Activating -> Active
2008-09-06 23:59:39,062 SCR Component Actor DEBUG osgi -
[DistributedSessions] Component activated
-> Why the following log reactivates the component ? I don't have any
configurations stored in the ConfigAdmin with pid="DistributedSessions" !
(notice that the log's thread is the Config Admin thread ...) :
2008-09-06 23:59:39,066 Configuration Updater DEBUG osgi -
[DistributedSessions] Deactivating and Activating to reconfigure from
configuration
2008-09-06 23:59:39,067 SCR Component Actor DEBUG osgi - [Dht] Enabling
component
2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht] State
transition : Disabled -> Enabled
2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht]
Component enabled
2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
transition : Enabled -> Activating
2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
Activating component
2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
transition : Activating -> Registered
2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
registering services
2008-09-06 23:59:39,066 FelixStartLevel DEBUG osgi - [DhtReg"]
ManagerFactory.createManager
2008-09-06 23:59:39,073 FelixStartLevel DEBUG osgi - [DhtReg] Component
created
2008-09-06 23:59:39,075 Configuration Updater DEBUG osgi - [Dht]
Deactivating and Activating to reconfigure from configuration
2008-09-06 23:59:39,078 SCR Component Actor DEBUG osgi - [Dht]
Component activated
2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Active -> Deactivating
2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
[ServiceLoader] Deactivating component
2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
[ServiceLoader] deactivate() method is not implemented
2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Deactivating -> Unsatisfied
2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
[ServiceLoader] Component deactivated
2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Unsatisfied -> Activating
2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
[ServiceLoader] Activating component
2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
[ServiceLoader] State transition : Activating -> Active
2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
[ServiceLoader] Component activated
2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
[DhtSessionDir] Enabling component
2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
[DhtSessionDir] State transition : Disabled -> Enabled
2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
[DhtSessionDir] Component enabled
2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
[DhtSessionDir] State transition : Enabled -> Activating
2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
[DhtSessionDir] Activating component
2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
[DhtSessionDir] State transition : Activating -> Registered
2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
[DhtSessionDir] registering services
2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
[DhtSessionDir] Component activated
2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
[DistributedSessions] State transition : Active -> Deactivating
2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
[DistributedSessions] Deactivating component
2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
[DistributedSessions] State transition : Deactivating -> Unsatisfied
2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
[DistributedSessions] Component deactivated
2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
[DistributedSessions] State transition : Unsatisfied -> Activating
2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
[DistributedSessions] Activating component
I am not really certain, but my undestanding is the following: The SCR
actually registers a ManagedService in the OSGi service registry in
order to provide eventual configurations to the component. But it
sounds like the SCR starts activating the
"DistributedSessions" component before (FIXME ?) being called back in
"ManagedService.updated" method. So, sometimes, when the
"DistributedSessions" is activated quickly, it is then just restarted.
Please have a look in the SCR source code, especially in
ImmediateComponentManager.java:
The constructor registers a ManagedService for my "DistributedSessions"
component:
ImmediateComponentManager( BundleComponentActivator activator,
ComponentMetadata metadata, long componentId )
{
...
// register an anonymous managed service instance
ManagedService ms = new ManagedService()
{
public void updated( Dictionary properties )
{
reconfigure( properties );
}
};
public void reconfigure( Dictionary configuration )
{
// store the properties
m_configurationProperties = configuration;
// clear the current properties to force using the configuration
data
m_properties = null;
// reactivate the component to ensure it is provided with the
// configuration data
if ( ( getState() & ( STATE_ACTIVE | STATE_FACTORY |
STATE_REGISTERED ) ) != 0 )
{
log( LogService.LOG_DEBUG, "Deactivating and Activating to
reconfigure from configuration",
getComponentMetadata(), null );
reactivateAsynchronous();
}
}
-> So, did I miss something, or is it a concurrency bug ?
Is SCR really waiting for the initial ManagedService callback, before
starting to activate components ?
Thanks for your help.
/pierre
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
For additional commands, e-mail: users-help@felix.apache.org
Re: SCR/ unexpected component reactivation while starting up JVM
Posted by Felix Meschberger <fm...@gmail.com>.
Hi Pierre,
Pierre De Rop schrieb:
> Hi Felix and thank you for looking at this problem.
>
> This is an issue for us, because we are using the DS in our application
> server,
> which runs in a clustered environment; and appserver deactivation may lead
> to many alarms and network messages, so it would be great to have a fix,
> even
> in the trunk.
I perfectly understand. And I try to provide a fix asap ;-)
> By the way, I'm wondering why you don't just wait for the initial
> managed service callback before
> initiating the component activation ?
> Indeed, when you register a ManagedService, the configadmin always
> callback on the "updated" method
> (and the dictionary is null if there is no properties). This way, you
> would then be certain that config admin
> don't invoke the initial "updated" method while the component is active
> (I hope that what I am saying make sense for you).
The point is, that this is all asynchronous: I can register a
ManagedService without even caring for the existence of a Configuration
Admin Service. So I cannot wait for the Configuration Admin Service to
provide something -- I just don't know whether and when that something
will arrive.
Best I can do is register and continue. If timing is "slow", the
component will not be restarted. Otherwise the component is restarted.
In fact, the component needs to be restarted everytime the Configuration
Admin calls the update method. The only point in time, where the SCR may
be acting somewhat more loosely is, when the component has just been
started without the configuration and the Configuration Admin sends
"null" configuration.
Hope this helps.
Regards
Felix
>
> Best Regards
> /pierre
>
> Felix Meschberger wrote:
>> Hi Pierre,
>>
>> This is an annoyance, I agree. What actually happens is this:
>>
>> * SCR registeres a ManagedService on behalf of the component
>> * SCR activates the component
>> * ConfigAdmin informs the ManagedService about configuration
>> (in this case there is none, and null used)
>> * SCR cycles the component to inject the new configuration
>>
>> This situation does not happen all the time, because there may be times
>> that the ConfigAdmin notifies the ManagedService before the component
>> has actually been activated. In this case the restart is not done.
>>
>> To fix this, we have multiple options: Insert a delay between
>> registering the ManagedService and activating the component to give
>> ConfigAdmin a chance to inject initial configuration. I do not
>> particularly like this option.
>>
>> A second option would be to ignore the first ManagedService.updated call
>> for a component if the parameter is null. Because this just indicates,
>> that the ConfigAdmin has no configuration and thus the component does
>> not need to be reconfigured.
>>
>> This second option, of course does not prevent re-activation in case a
>> configuration actually present, but I think, this is the way of life ...
>>
>> I created https://issues.apache.org/jira/browse/FELIX-714 to track this
>> issue.
>>
>> Hope this helps.
>>
>> Regards
>> Felix
>>
>>
>>
>> Pierre De Rop schrieb:
>>
>>> Hi everyone;
>>>
>>> I recently noticed a strange behaviour with Declarative Services.
>>> Sometimes (rarely, but it happens), I see that my SCR components are
>>> activated twice at jvm startup time.
>>>
>>> Did anyone came across the same problem ?
>>>
>>> I know that a component must expect to be deactivated/reactivated
>>> (after a bundle update, or after a ConfigAdmin update for example),
>>> But in my case, the problem occurs at startup (there is no bundle
>>> update, and I don't use the ConfigAdmin service at all for my
>>> components configurations).
>>>
>>> I have the following components for our Alcatel-Lucent Distributed
>>> Hashtable Service:
>>>
>>> "ServiceLoader"
>>> "DistributedSessions"
>>> "Dht"
>>> "DhtReg"
>>>
>>> and in the following SCR log, around 23:59:39,066, you will see that
>>> "DistributedSessions" component is deactivated/reactivated:
>>>
>>> Here are the logs (please see my comments after the logs):
>>>
>>> 2008-09-06 23:59:39,012 FelixStartLevel DEBUG osgi - [ServiceLoader]
>>> ManagerFactory.createManager
>>> 2008-09-06 23:59:39,019 FelixStartLevel DEBUG osgi - [ServiceLoader]
>>> Component created
>>> 2008-09-06 23:59:39,037 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Enabling component
>>> 2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
>>> [DistributedSessions] ManagerFactory.createManager
>>> 2008-09-06 23:59:39,038 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Disabled -> Enabled
>>> 2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
>>> [DistributedSessions] Component created
>>> 2008-09-06 23:59:39,039 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Component enabled
>>> 2008-09-06 23:59:39,041 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Enabled -> Activating
>>> 2008-09-06 23:59:39,043 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Activating component
>>> 2008-09-06 23:59:39,047 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Activating -> Active
>>> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Component activated
>>> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Enabling component
>>> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] State transition : Disabled -> Enabled
>>> 2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Component enabled
>>> 2008-09-06 23:59:39,049 FelixStartLevel DEBUG osgi - [Dht]
>>> ManagerFactory.createManager
>>> 2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] State transition : Enabled -> Activating
>>> 2008-09-06 23:59:39,050 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Activating component
>>> 2008-09-06 23:59:39,050 FelixStartLevel DEBUG osgi - [Dht] Component
>>> created
>>> 2008-09-06 23:59:39,055 FelixStartLevel DEBUG osgi - [DhtSessionDir]
>>> ManagerFactory.createManager
>>> 2008-09-06 23:59:39,058 FelixStartLevel DEBUG osgi - [DhtSessionDir]
>>> Component created
>>> 2008-09-06 23:59:39,055 Configuration Updater DEBUG osgi -
>>> [ServiceLoader] Deactivating and Activating to reconfigure from
>>> configuration
>>> 2008-09-06 23:59:39,061 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] State transition : Activating -> Active
>>> 2008-09-06 23:59:39,062 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Component activated
>>>
>>> -> Why the following log reactivates the component ? I don't have any
>>> configurations stored in the ConfigAdmin with
>>> pid="DistributedSessions" !
>>> (notice that the log's thread is the Config Admin thread ...) :
>>> 2008-09-06 23:59:39,066 Configuration Updater DEBUG osgi -
>>> [DistributedSessions] Deactivating and Activating to reconfigure from
>>> configuration
>>>
>>> 2008-09-06 23:59:39,067 SCR Component Actor DEBUG osgi - [Dht] Enabling
>>> component
>>> 2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht] State
>>> transition : Disabled -> Enabled
>>> 2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht]
>>> Component enabled
>>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
>>> transition : Enabled -> Activating
>>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
>>> Activating component
>>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
>>> transition : Activating -> Registered
>>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
>>> registering services
>>> 2008-09-06 23:59:39,066 FelixStartLevel DEBUG osgi - [DhtReg"]
>>> ManagerFactory.createManager
>>> 2008-09-06 23:59:39,073 FelixStartLevel DEBUG osgi - [DhtReg] Component
>>> created
>>> 2008-09-06 23:59:39,075 Configuration Updater DEBUG osgi - [Dht]
>>> Deactivating and Activating to reconfigure from configuration
>>> 2008-09-06 23:59:39,078 SCR Component Actor DEBUG osgi - [Dht]
>>> Component activated
>>> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Active -> Deactivating
>>> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Deactivating component
>>> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] deactivate() method is not implemented
>>> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Deactivating -> Unsatisfied
>>> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Component deactivated
>>> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Unsatisfied -> Activating
>>> 2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Activating component
>>> 2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] State transition : Activating -> Active
>>> 2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
>>> [ServiceLoader] Component activated
>>> 2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] Enabling component
>>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] State transition : Disabled -> Enabled
>>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] Component enabled
>>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] State transition : Enabled -> Activating
>>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] Activating component
>>> 2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] State transition : Activating -> Registered
>>> 2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] registering services
>>> 2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
>>> [DhtSessionDir] Component activated
>>> 2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] State transition : Active -> Deactivating
>>> 2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Deactivating component
>>> 2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] State transition : Deactivating -> Unsatisfied
>>> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Component deactivated
>>> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] State transition : Unsatisfied -> Activating
>>> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
>>> [DistributedSessions] Activating component
>>>
>>> I am not really certain, but my undestanding is the following: The SCR
>>> actually registers a ManagedService in the OSGi service registry in
>>> order to provide eventual configurations to the component. But it
>>> sounds like the SCR starts activating the
>>> "DistributedSessions" component before (FIXME ?) being called back in
>>> "ManagedService.updated" method. So, sometimes, when the
>>> "DistributedSessions" is activated quickly, it is then just restarted.
>>> Please have a look in the SCR source code, especially in
>>> ImmediateComponentManager.java:
>>>
>>> The constructor registers a ManagedService for my "DistributedSessions"
>>> component:
>>>
>>> ImmediateComponentManager( BundleComponentActivator activator,
>>> ComponentMetadata metadata, long componentId )
>>> {
>>> ...
>>> // register an anonymous managed service instance
>>> ManagedService ms = new ManagedService()
>>> {
>>> public void updated( Dictionary properties )
>>> {
>>> reconfigure( properties );
>>> }
>>> };
>>>
>>>
>>> public void reconfigure( Dictionary configuration )
>>> {
>>> // store the properties
>>> m_configurationProperties = configuration;
>>>
>>> // clear the current properties to force using the configuration
>>> data
>>> m_properties = null;
>>>
>>> // reactivate the component to ensure it is provided with the
>>> // configuration data
>>> if ( ( getState() & ( STATE_ACTIVE | STATE_FACTORY |
>>> STATE_REGISTERED ) ) != 0 )
>>> {
>>> log( LogService.LOG_DEBUG, "Deactivating and Activating to
>>> reconfigure from configuration",
>>> getComponentMetadata(), null );
>>> reactivateAsynchronous();
>>> }
>>> }
>>>
>>> -> So, did I miss something, or is it a concurrency bug ?
>>> Is SCR really waiting for the initial ManagedService callback, before
>>> starting to activate components ?
>>>
>>> Thanks for your help.
>>> /pierre
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
>>> For additional commands, e-mail: users-help@felix.apache.org
>>>
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
>> For additional commands, e-mail: users-help@felix.apache.org
>>
>>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
For additional commands, e-mail: users-help@felix.apache.org
Re: SCR/ unexpected component reactivation while starting up JVM
Posted by Pierre De Rop <pi...@alcatel-lucent.fr>.
Hi Felix and thank you for looking at this problem.
This is an issue for us, because we are using the DS in our application
server,
which runs in a clustered environment; and appserver deactivation may lead
to many alarms and network messages, so it would be great to have a fix,
even
in the trunk.
By the way, I'm wondering why you don't just wait for the initial
managed service callback before
initiating the component activation ?
Indeed, when you register a ManagedService, the configadmin always
callback on the "updated" method
(and the dictionary is null if there is no properties). This way, you
would then be certain that config admin
don't invoke the initial "updated" method while the component is active
(I hope that what I am saying make sense for you).
Best Regards
/pierre
Felix Meschberger wrote:
> Hi Pierre,
>
> This is an annoyance, I agree. What actually happens is this:
>
> * SCR registeres a ManagedService on behalf of the component
> * SCR activates the component
> * ConfigAdmin informs the ManagedService about configuration
> (in this case there is none, and null used)
> * SCR cycles the component to inject the new configuration
>
> This situation does not happen all the time, because there may be times
> that the ConfigAdmin notifies the ManagedService before the component
> has actually been activated. In this case the restart is not done.
>
> To fix this, we have multiple options: Insert a delay between
> registering the ManagedService and activating the component to give
> ConfigAdmin a chance to inject initial configuration. I do not
> particularly like this option.
>
> A second option would be to ignore the first ManagedService.updated call
> for a component if the parameter is null. Because this just indicates,
> that the ConfigAdmin has no configuration and thus the component does
> not need to be reconfigured.
>
> This second option, of course does not prevent re-activation in case a
> configuration actually present, but I think, this is the way of life ...
>
> I created https://issues.apache.org/jira/browse/FELIX-714 to track this
> issue.
>
> Hope this helps.
>
> Regards
> Felix
>
>
>
> Pierre De Rop schrieb:
>
>> Hi everyone;
>>
>> I recently noticed a strange behaviour with Declarative Services.
>> Sometimes (rarely, but it happens), I see that my SCR components are
>> activated twice at jvm startup time.
>>
>> Did anyone came across the same problem ?
>>
>> I know that a component must expect to be deactivated/reactivated
>> (after a bundle update, or after a ConfigAdmin update for example),
>> But in my case, the problem occurs at startup (there is no bundle
>> update, and I don't use the ConfigAdmin service at all for my
>> components configurations).
>>
>> I have the following components for our Alcatel-Lucent Distributed
>> Hashtable Service:
>>
>> "ServiceLoader"
>> "DistributedSessions"
>> "Dht"
>> "DhtReg"
>>
>> and in the following SCR log, around 23:59:39,066, you will see that
>> "DistributedSessions" component is deactivated/reactivated:
>>
>> Here are the logs (please see my comments after the logs):
>>
>> 2008-09-06 23:59:39,012 FelixStartLevel DEBUG osgi - [ServiceLoader]
>> ManagerFactory.createManager
>> 2008-09-06 23:59:39,019 FelixStartLevel DEBUG osgi - [ServiceLoader]
>> Component created
>> 2008-09-06 23:59:39,037 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Enabling component
>> 2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
>> [DistributedSessions] ManagerFactory.createManager
>> 2008-09-06 23:59:39,038 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Disabled -> Enabled
>> 2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
>> [DistributedSessions] Component created
>> 2008-09-06 23:59:39,039 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Component enabled
>> 2008-09-06 23:59:39,041 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Enabled -> Activating
>> 2008-09-06 23:59:39,043 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Activating component
>> 2008-09-06 23:59:39,047 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Activating -> Active
>> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Component activated
>> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Enabling component
>> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] State transition : Disabled -> Enabled
>> 2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Component enabled
>> 2008-09-06 23:59:39,049 FelixStartLevel DEBUG osgi - [Dht]
>> ManagerFactory.createManager
>> 2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] State transition : Enabled -> Activating
>> 2008-09-06 23:59:39,050 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Activating component
>> 2008-09-06 23:59:39,050 FelixStartLevel DEBUG osgi - [Dht] Component
>> created
>> 2008-09-06 23:59:39,055 FelixStartLevel DEBUG osgi - [DhtSessionDir]
>> ManagerFactory.createManager
>> 2008-09-06 23:59:39,058 FelixStartLevel DEBUG osgi - [DhtSessionDir]
>> Component created
>> 2008-09-06 23:59:39,055 Configuration Updater DEBUG osgi -
>> [ServiceLoader] Deactivating and Activating to reconfigure from
>> configuration
>> 2008-09-06 23:59:39,061 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] State transition : Activating -> Active
>> 2008-09-06 23:59:39,062 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Component activated
>>
>> -> Why the following log reactivates the component ? I don't have any
>> configurations stored in the ConfigAdmin with pid="DistributedSessions" !
>> (notice that the log's thread is the Config Admin thread ...) :
>> 2008-09-06 23:59:39,066 Configuration Updater DEBUG osgi -
>> [DistributedSessions] Deactivating and Activating to reconfigure from
>> configuration
>>
>> 2008-09-06 23:59:39,067 SCR Component Actor DEBUG osgi - [Dht] Enabling
>> component
>> 2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht] State
>> transition : Disabled -> Enabled
>> 2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht]
>> Component enabled
>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
>> transition : Enabled -> Activating
>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
>> Activating component
>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
>> transition : Activating -> Registered
>> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
>> registering services
>> 2008-09-06 23:59:39,066 FelixStartLevel DEBUG osgi - [DhtReg"]
>> ManagerFactory.createManager
>> 2008-09-06 23:59:39,073 FelixStartLevel DEBUG osgi - [DhtReg] Component
>> created
>> 2008-09-06 23:59:39,075 Configuration Updater DEBUG osgi - [Dht]
>> Deactivating and Activating to reconfigure from configuration
>> 2008-09-06 23:59:39,078 SCR Component Actor DEBUG osgi - [Dht]
>> Component activated
>> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Active -> Deactivating
>> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Deactivating component
>> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] deactivate() method is not implemented
>> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Deactivating -> Unsatisfied
>> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Component deactivated
>> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Unsatisfied -> Activating
>> 2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Activating component
>> 2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] State transition : Activating -> Active
>> 2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
>> [ServiceLoader] Component activated
>> 2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] Enabling component
>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] State transition : Disabled -> Enabled
>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] Component enabled
>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] State transition : Enabled -> Activating
>> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] Activating component
>> 2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] State transition : Activating -> Registered
>> 2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] registering services
>> 2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
>> [DhtSessionDir] Component activated
>> 2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] State transition : Active -> Deactivating
>> 2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Deactivating component
>> 2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] State transition : Deactivating -> Unsatisfied
>> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Component deactivated
>> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] State transition : Unsatisfied -> Activating
>> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
>> [DistributedSessions] Activating component
>>
>> I am not really certain, but my undestanding is the following: The SCR
>> actually registers a ManagedService in the OSGi service registry in
>> order to provide eventual configurations to the component. But it
>> sounds like the SCR starts activating the
>> "DistributedSessions" component before (FIXME ?) being called back in
>> "ManagedService.updated" method. So, sometimes, when the
>> "DistributedSessions" is activated quickly, it is then just restarted.
>> Please have a look in the SCR source code, especially in
>> ImmediateComponentManager.java:
>>
>> The constructor registers a ManagedService for my "DistributedSessions"
>> component:
>>
>> ImmediateComponentManager( BundleComponentActivator activator,
>> ComponentMetadata metadata, long componentId )
>> {
>> ...
>> // register an anonymous managed service instance
>> ManagedService ms = new ManagedService()
>> {
>> public void updated( Dictionary properties )
>> {
>> reconfigure( properties );
>> }
>> };
>>
>>
>> public void reconfigure( Dictionary configuration )
>> {
>> // store the properties
>> m_configurationProperties = configuration;
>>
>> // clear the current properties to force using the configuration
>> data
>> m_properties = null;
>>
>> // reactivate the component to ensure it is provided with the
>> // configuration data
>> if ( ( getState() & ( STATE_ACTIVE | STATE_FACTORY |
>> STATE_REGISTERED ) ) != 0 )
>> {
>> log( LogService.LOG_DEBUG, "Deactivating and Activating to
>> reconfigure from configuration",
>> getComponentMetadata(), null );
>> reactivateAsynchronous();
>> }
>> }
>>
>> -> So, did I miss something, or is it a concurrency bug ?
>> Is SCR really waiting for the initial ManagedService callback, before
>> starting to activate components ?
>>
>> Thanks for your help.
>> /pierre
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
>> For additional commands, e-mail: users-help@felix.apache.org
>>
>>
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
> For additional commands, e-mail: users-help@felix.apache.org
>
>
Re: SCR/ unexpected component reactivation while starting up JVM
Posted by Felix Meschberger <fm...@gmail.com>.
Hi Pierre,
This is an annoyance, I agree. What actually happens is this:
* SCR registeres a ManagedService on behalf of the component
* SCR activates the component
* ConfigAdmin informs the ManagedService about configuration
(in this case there is none, and null used)
* SCR cycles the component to inject the new configuration
This situation does not happen all the time, because there may be times
that the ConfigAdmin notifies the ManagedService before the component
has actually been activated. In this case the restart is not done.
To fix this, we have multiple options: Insert a delay between
registering the ManagedService and activating the component to give
ConfigAdmin a chance to inject initial configuration. I do not
particularly like this option.
A second option would be to ignore the first ManagedService.updated call
for a component if the parameter is null. Because this just indicates,
that the ConfigAdmin has no configuration and thus the component does
not need to be reconfigured.
This second option, of course does not prevent re-activation in case a
configuration actually present, but I think, this is the way of life ...
I created https://issues.apache.org/jira/browse/FELIX-714 to track this
issue.
Hope this helps.
Regards
Felix
Pierre De Rop schrieb:
> Hi everyone;
>
> I recently noticed a strange behaviour with Declarative Services.
> Sometimes (rarely, but it happens), I see that my SCR components are
> activated twice at jvm startup time.
>
> Did anyone came across the same problem ?
>
> I know that a component must expect to be deactivated/reactivated
> (after a bundle update, or after a ConfigAdmin update for example),
> But in my case, the problem occurs at startup (there is no bundle
> update, and I don't use the ConfigAdmin service at all for my
> components configurations).
>
> I have the following components for our Alcatel-Lucent Distributed
> Hashtable Service:
>
> "ServiceLoader"
> "DistributedSessions"
> "Dht"
> "DhtReg"
>
> and in the following SCR log, around 23:59:39,066, you will see that
> "DistributedSessions" component is deactivated/reactivated:
>
> Here are the logs (please see my comments after the logs):
>
> 2008-09-06 23:59:39,012 FelixStartLevel DEBUG osgi - [ServiceLoader]
> ManagerFactory.createManager
> 2008-09-06 23:59:39,019 FelixStartLevel DEBUG osgi - [ServiceLoader]
> Component created
> 2008-09-06 23:59:39,037 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Enabling component
> 2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
> [DistributedSessions] ManagerFactory.createManager
> 2008-09-06 23:59:39,038 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Disabled -> Enabled
> 2008-09-06 23:59:39,038 FelixStartLevel DEBUG osgi -
> [DistributedSessions] Component created
> 2008-09-06 23:59:39,039 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Component enabled
> 2008-09-06 23:59:39,041 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Enabled -> Activating
> 2008-09-06 23:59:39,043 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Activating component
> 2008-09-06 23:59:39,047 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Activating -> Active
> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Component activated
> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Enabling component
> 2008-09-06 23:59:39,048 SCR Component Actor DEBUG osgi -
> [DistributedSessions] State transition : Disabled -> Enabled
> 2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Component enabled
> 2008-09-06 23:59:39,049 FelixStartLevel DEBUG osgi - [Dht]
> ManagerFactory.createManager
> 2008-09-06 23:59:39,049 SCR Component Actor DEBUG osgi -
> [DistributedSessions] State transition : Enabled -> Activating
> 2008-09-06 23:59:39,050 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Activating component
> 2008-09-06 23:59:39,050 FelixStartLevel DEBUG osgi - [Dht] Component
> created
> 2008-09-06 23:59:39,055 FelixStartLevel DEBUG osgi - [DhtSessionDir]
> ManagerFactory.createManager
> 2008-09-06 23:59:39,058 FelixStartLevel DEBUG osgi - [DhtSessionDir]
> Component created
> 2008-09-06 23:59:39,055 Configuration Updater DEBUG osgi -
> [ServiceLoader] Deactivating and Activating to reconfigure from
> configuration
> 2008-09-06 23:59:39,061 SCR Component Actor DEBUG osgi -
> [DistributedSessions] State transition : Activating -> Active
> 2008-09-06 23:59:39,062 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Component activated
>
> -> Why the following log reactivates the component ? I don't have any
> configurations stored in the ConfigAdmin with pid="DistributedSessions" !
> (notice that the log's thread is the Config Admin thread ...) :
> 2008-09-06 23:59:39,066 Configuration Updater DEBUG osgi -
> [DistributedSessions] Deactivating and Activating to reconfigure from
> configuration
>
> 2008-09-06 23:59:39,067 SCR Component Actor DEBUG osgi - [Dht] Enabling
> component
> 2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht] State
> transition : Disabled -> Enabled
> 2008-09-06 23:59:39,071 SCR Component Actor DEBUG osgi - [Dht]
> Component enabled
> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
> transition : Enabled -> Activating
> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
> Activating component
> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht] State
> transition : Activating -> Registered
> 2008-09-06 23:59:39,072 SCR Component Actor DEBUG osgi - [Dht]
> registering services
> 2008-09-06 23:59:39,066 FelixStartLevel DEBUG osgi - [DhtReg"]
> ManagerFactory.createManager
> 2008-09-06 23:59:39,073 FelixStartLevel DEBUG osgi - [DhtReg] Component
> created
> 2008-09-06 23:59:39,075 Configuration Updater DEBUG osgi - [Dht]
> Deactivating and Activating to reconfigure from configuration
> 2008-09-06 23:59:39,078 SCR Component Actor DEBUG osgi - [Dht]
> Component activated
> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Active -> Deactivating
> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Deactivating component
> 2008-09-06 23:59:39,079 SCR Component Actor DEBUG osgi -
> [ServiceLoader] deactivate() method is not implemented
> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Deactivating -> Unsatisfied
> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Component deactivated
> 2008-09-06 23:59:39,080 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Unsatisfied -> Activating
> 2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Activating component
> 2008-09-06 23:59:39,081 SCR Component Actor DEBUG osgi -
> [ServiceLoader] State transition : Activating -> Active
> 2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
> [ServiceLoader] Component activated
> 2008-09-06 23:59:39,083 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] Enabling component
> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] State transition : Disabled -> Enabled
> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] Component enabled
> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] State transition : Enabled -> Activating
> 2008-09-06 23:59:39,084 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] Activating component
> 2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] State transition : Activating -> Registered
> 2008-09-06 23:59:39,085 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] registering services
> 2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
> [DhtSessionDir] Component activated
> 2008-09-06 23:59:39,086 SCR Component Actor DEBUG osgi -
> [DistributedSessions] State transition : Active -> Deactivating
> 2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Deactivating component
> 2008-09-06 23:59:39,087 SCR Component Actor DEBUG osgi -
> [DistributedSessions] State transition : Deactivating -> Unsatisfied
> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Component deactivated
> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
> [DistributedSessions] State transition : Unsatisfied -> Activating
> 2008-09-06 23:59:39,088 SCR Component Actor DEBUG osgi -
> [DistributedSessions] Activating component
>
> I am not really certain, but my undestanding is the following: The SCR
> actually registers a ManagedService in the OSGi service registry in
> order to provide eventual configurations to the component. But it
> sounds like the SCR starts activating the
> "DistributedSessions" component before (FIXME ?) being called back in
> "ManagedService.updated" method. So, sometimes, when the
> "DistributedSessions" is activated quickly, it is then just restarted.
> Please have a look in the SCR source code, especially in
> ImmediateComponentManager.java:
>
> The constructor registers a ManagedService for my "DistributedSessions"
> component:
>
> ImmediateComponentManager( BundleComponentActivator activator,
> ComponentMetadata metadata, long componentId )
> {
> ...
> // register an anonymous managed service instance
> ManagedService ms = new ManagedService()
> {
> public void updated( Dictionary properties )
> {
> reconfigure( properties );
> }
> };
>
>
> public void reconfigure( Dictionary configuration )
> {
> // store the properties
> m_configurationProperties = configuration;
>
> // clear the current properties to force using the configuration
> data
> m_properties = null;
>
> // reactivate the component to ensure it is provided with the
> // configuration data
> if ( ( getState() & ( STATE_ACTIVE | STATE_FACTORY |
> STATE_REGISTERED ) ) != 0 )
> {
> log( LogService.LOG_DEBUG, "Deactivating and Activating to
> reconfigure from configuration",
> getComponentMetadata(), null );
> reactivateAsynchronous();
> }
> }
>
> -> So, did I miss something, or is it a concurrency bug ?
> Is SCR really waiting for the initial ManagedService callback, before
> starting to activate components ?
>
> Thanks for your help.
> /pierre
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
> For additional commands, e-mail: users-help@felix.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@felix.apache.org
For additional commands, e-mail: users-help@felix.apache.org