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: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
