Pierre De Rop created FELIX-3639:
------------------------------------
Summary: SCR "need write lock" assertion error in
Key: FELIX-3639
URL: https://issues.apache.org/jira/browse/FELIX-3639
Project: Felix
Issue Type: Bug
Components: Declarative Services (SCR)
Environment: openjdk version "1.6.0-OpenSCG-Build-24", on Red Hat
Enterprise Linux Server release 5.4 (Tikanga)
Reporter: Pierre De Rop
Attachments: NeedWriteLock.log
This issue is related to the post
http://www.mail-archive.com/[email protected]/msg26360.html.
Initially, the post was about an apparent deadlock, where SCR can't obtain its
state lock timely.
But after having added some tracking code in SCR, we came across another
(probably different) problem,
where the "need write lock (createComponent)" assertion fails from the
ImmediateComponentManager.createComponent() method.
In order to see the full stacktrace, I have modified the
ImmediateComponentManager.createComponent method with a log, like this:
protected boolean createComponent()
{
if ( !isWriteLocked() )
{
log(LogService.LOG_ERROR, "need write lock (createComponent)", new
Object[0], new Exception("stacktrace")); throw new IllegalStateException( "need
write lock (createComponent)" );
}
...
(I just added a log with a "stacktrace" exception, just before throwing the
illegal state).
I have attached the full log to this issue, with ds.loglevel set to DEBUG.
Please take a look at line line 8143, where the assertion fails.
It's difficult to explain the whole context, but I will try to give a quick
overview:
1- the "sipagent" component is declared like this (we are using bnd DS
annotations):
@Component(name="sipagent",provide={com.nextenso.mux.MuxHandler.class,SipAgent.class},properties=("protocol=sip"),configurationPolicy=ConfigurationPolicy.require,factory="composite.sip")
public class SipAgentActivator extends SipAgent implements ServiceListener {
...
}
Here, the SipAgentActivator class actually extends SipAgent, which extends the
MuxHandler abstract class, and the MuxHandler abstract class is provided as an
OSGi service, using a "protocol=sip" service property.
The "sipagent" component is also declared as a factory component (with
name="composite.sip"), and another manager is in charge of instantiating the
"sipagent" component instances (using ComponentFactory.newInstance() method).
When the sip message load increases, more sipagent component instances are
created.
2- when one "sipagent" component instance is created, there is another tracking
"agent" component, which has a Reference on the MuxHandler interface, provided
by the "sipagent" component. We use a ServiceReference. Here is how the "agent"
component defines its reference:
@Component(name = "agent", configurationPolicy = ConfigurationPolicy.require)
public class Agent {
@Reference(service = MuxHandler.class, type = '*', unbind =
"unbindMuxHandler")
public void bindMuxHandler(final ServiceReference<?> muxHandler) {
_logger.info("bound mux handler (protocol=%s)",
muxHandler.getProperty("protocol"));
_serial.execute(new Runnable() {
public void run() {
if (!_started) {
_pendingMuxHandlers.add(muxHandler);
} else {
...
Here, the "agent" is tracking every mux handlers, but if the "agent" component
is not yet started, then the mux handler is simply stored in the
"pendingMuxHandlers" temporary list. The _serial object is a serial executor,
used to avoid synchronized methods.
3- The "agent" component also have a Reference on a "SessionManager" service,
and when this service is injected, then then the "agent" component decides to
handle the sip MuxHandler stored in the pendingMuxHandlers temporary list. At
this point, the "agent" gets the MuxHandler ServiceReference from the temporary
list, and directly calls BundleContext.getService(ServiceReference), in order
to get the pointer to the actual MuxHandler object.
But the BundleContext.getService method returns null, and internally, the
ImmediateComponentManager.createComponent has throws an IllegalStateException
because the writelock has not been aquired.
See stacktrace, starting from line 8143 (it is the log I have added in the
ImmediateComponentManager.createComponent method):
2012-08-27 13:07:45,909 Processing-ThreadPool-10 ERROR osgi - [sipagent] need
write lock (createComponent)
java.lang.Exception: stacktrace
at
org.apache.felix.scr.impl.manager.ImmediateComponentManager.createComponent(ImmediateComponentManager.java:123)
at
org.apache.felix.scr.impl.manager.AbstractComponentManager$FactoryInstance.getService(AbstractComponentManager.java:1570)
at
org.apache.felix.scr.impl.manager.ImmediateComponentManager.getService(ImmediateComponentManager.java:632)
at
org.apache.felix.framework.ServiceRegistrationImpl.getFactoryUnchecked(ServiceRegistrationImpl.java:308)
at
org.apache.felix.framework.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:219)
at
org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:310)
at org.apache.felix.framework.Felix.getService(Felix.java:3420)
at
org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:468)
at com.nextenso.agent.Agent$9.run(Agent.java:427)
at
com.alcatel.as.service.concurrent.SerialExecutor.execute(SerialExecutor.java:41)
at com.nextenso.agent.Agent.bindSessionManager(Agent.java:362)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at
org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:226)
at
org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)
at
org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:603)
at
org.apache.felix.scr.impl.helper.BaseMethod$NotResolved.invoke(BaseMethod.java:560)
at
org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:484)
at
org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:1086)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceAdded(DependencyManager.java:328)
at
org.apache.felix.scr.impl.manager.DependencyManager.serviceChanged(DependencyManager.java:170)
at
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCallback(EventDispatcher.java:932)
at
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:793)
at
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDispatcher.java:543)
at org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:4260)
at org.apache.felix.framework.Felix.registerService(Felix.java:3275)
at
org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:346)
at
org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:320)
at
com.alcatel.as.util.osgi.DependencyActivatorHelper.registerService(DependencyActivatorHelper.java:209)
at com.alcatel.as.session.distributed.mgr.Engine$7.run(Engine.java:1383)
at com.alcatel.as.service.concurrent.impl.Helper.runTask(Helper.java:54)
at
com.alcatel.as.service.concurrent.impl.QueueExecutor$1.run(QueueExecutor.java:165)
at
com.alcatel.as.service.concurrent.impl.SerialQueue.run(SerialQueue.java:80)
at
alcatel.tess.hometop.gateways.concurrent.ThreadPool$3.run(ThreadPool.java:286)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Is the attached log enough with ds.loglevel=DEBUG, or do you need some more
informations ?
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
