OK - worked it out.
It was not an issue with CXF or really with Felix. I had two logging
services running within Felix,
The Felix logging service, and the OPS4J logging service (which I added
for the OPS4J Web service).
After removing the Felix log service, everything started up fine without
any deadlocks.
Regards,
Chris Clark
Senior developer
Vodafone NL Account
EDS MtI Team
EDS, an HP Company
Avenue Ceramique 241
6221 KX Maastricht NL
Chamber of Commerce: 27161118
Office: +31 887501769
Mobile: +31 6 15036556
Web: www.eds.nl <http://www.eds.nl/>
This email contains information which is
confidential and may be privileged. Unless you are the intended
addressee (or authorised to receive for the addressee) you may not use,
forward, copy or disclose to anyone this email or any information
contained in this email. If you have received this email in error,
please advise the sender by reply email immediately and delete this
email.
_____________________________________________
From: Clark, Chris
Sent: 30 July 2009 10:08
To: '[email protected]'
Subject: Deadlock in CXF DOSGi implementation (latest
1.1 snapshot)
Hi
When trying to use the latest CXF DOSGi RI (multibundle)
together with Apache Felix 1.8.1 I noticed a thread deadlock when
starting
Up - this occurs on the startup of the last bundle in
the list, cxf-dosgi-ri-dsw-cxf-1.1-SNAPSHOT.jar.
The last log entry I see is:
[FelixStartLevel] INFO
org.apache.cxf.dosgi.dsw.hooks.AbstractClientHook - looku
p discovery service: interface:
org.osgi.service.event.EventHandler filter: (|(e
vent.topics=\*)(event.topics=org/\*)(event.topics=org/osgi/\*)(event.top
ics=org/
osgi/service/\*)(event.topics=org/osgi/service/log/\*)(event.topics=org/
osgi/ser
vice/log/LogEntry/\*)(event.topics=org/osgi/service/log/LogEntry/LOG_DEB
UG))
[9818...@qtp-4171180-0 - /system/console/logs] DEBUG
org.mortbay.jetty - REQUEST
/system/console/logs on
org.mortbay.jetty.httpconnect...@19b808a
When using jconsole (I am running on JDK 6.0 u14), these
are the deadlocks:
[1]
Name: FelixStartLevel
State: BLOCKED on java.util.st...@39f16f owned by:
Thread-4
Total blocked: 70 Total waited: 46
Stack trace:
org.apache.felix.log.LogListenerThread.addEntry(LogListenerThread.java:5
2)
org.apache.felix.log.Log.addEntry(Log.java:125)
- locked org.apache.felix.log....@1637d45
org.apache.felix.log.Log.serviceChanged(Log.java:263)
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCal
lback(EventDispatcher.java:846)
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(Eve
ntDispatcher.java:704)
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDi
spatcher.java:635)
org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:3443)
org.apache.felix.framework.Felix.access$000(Felix.java:39)
org.apache.felix.framework.Felix$1.serviceChanged(Felix.java:622)
org.apache.felix.framework.ServiceRegistry.fireServiceChanged(ServiceReg
istry.java:576)
org.apache.felix.framework.ServiceRegistry.servicePropertiesModified(Ser
viceRegistry.java:501)
org.apache.felix.framework.ServiceRegistrationImpl.setProperties(Service
RegistrationImpl.java:107)
org.apache.cxf.dosgi.dsw.hooks.AbstractClientHook.lookupDiscoveryService
(AbstractClientHook.java:218)
- locked
org.apache.cxf.dosgi.dsw.hooks.cxffindlistenerh...@1a0283e
org.apache.cxf.dosgi.dsw.hooks.CxfFindListenerHook.find(CxfFindListenerH
ook.java:95)
org.apache.felix.framework.Felix.getServiceReferences(Felix.java:2642)
org.apache.felix.framework.Felix.getAllowedServiceReferences(Felix.java:
2672)
org.apache.felix.framework.BundleContextImpl.getServiceReferences(Bundle
ContextImpl.java:310)
org.apache.felix.eventadmin.impl.handler.BlacklistingHandlerTasks.create
HandlerTasks(BlacklistingHandlerTasks.java:114)
org.apache.felix.eventadmin.impl.EventAdminImpl.postEvent(EventAdminImpl
.java:87)
org.apache.felix.eventadmin.impl.adapter.ServiceEventAdapter.serviceChan
ged(ServiceEventAdapter.java:135)
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCal
lback(EventDispatcher.java:846)
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(Eve
ntDispatcher.java:704)
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDi
spatcher.java:635)
org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:3443)
org.apache.felix.framework.Felix.access$000(Felix.java:39)
org.apache.felix.framework.Felix$1.serviceChanged(Felix.java:622)
org.apache.felix.framework.ServiceRegistry.fireServiceChanged(ServiceReg
istry.java:576)
org.apache.felix.framework.ServiceRegistry.servicePropertiesModified(Ser
viceRegistry.java:501)
org.apache.felix.framework.ServiceRegistrationImpl.setProperties(Service
RegistrationImpl.java:107)
org.apache.cxf.dosgi.dsw.hooks.AbstractClientHook.lookupDiscoveryService
(AbstractClientHook.java:218)
- locked
org.apache.cxf.dosgi.dsw.hooks.cxffindlistenerh...@1a0283e
org.apache.cxf.dosgi.dsw.hooks.CxfFindListenerHook.find(CxfFindListenerH
ook.java:95)
org.apache.felix.framework.Felix.getServiceReferences(Felix.java:2642)
org.apache.felix.framework.Felix.getAllowedServiceReferences(Felix.java:
2672)
org.apache.felix.framework.BundleContextImpl.getServiceReferences(Bundle
ContextImpl.java:310)
org.apache.felix.eventadmin.impl.handler.BlacklistingHandlerTasks.create
HandlerTasks(BlacklistingHandlerTasks.java:114)
org.apache.felix.eventadmin.impl.EventAdminImpl.postEvent(EventAdminImpl
.java:87)
org.apache.felix.eventadmin.impl.adapter.LogEventAdapter$1.logged(LogEve
ntAdapter.java:285)
org.ops4j.pax.logging.internal.LogReaderServiceImpl.fire(LogReaderServic
eImpl.java:129)
org.ops4j.pax.logging.internal.LogReaderServiceImpl.fireEvent(LogReaderS
erviceImpl.java:121)
org.ops4j.pax.logging.internal.PaxLoggingServiceImpl.handleEvents(PaxLog
gingServiceImpl.java:151)
org.ops4j.pax.logging.internal.PaxLoggerImpl.debug(PaxLoggerImpl.java:11
6)
org.ops4j.pax.logging.internal.PaxLoggingServiceImpl.log(PaxLoggingServi
ceImpl.java:140)
org.ops4j.pax.logging.internal.PaxLoggingServiceImpl.log(PaxLoggingServi
ceImpl.java:93)
org.ops4j.pax.logging.internal.PaxLoggingServiceImpl.log(PaxLoggingServi
ceImpl.java:88)
org.ops4j.pax.logging.internal.FrameworkHandler.serviceChanged(Framework
Handler.java:147)
org.apache.felix.framework.util.EventDispatcher.invokeServiceListenerCal
lback(EventDispatcher.java:846)
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(Eve
ntDispatcher.java:704)
org.apache.felix.framework.util.EventDispatcher.fireServiceEvent(EventDi
spatcher.java:635)
org.apache.felix.framework.Felix.fireServiceEvent(Felix.java:3443)
org.apache.felix.framework.Felix.access$000(Felix.java:39)
org.apache.felix.framework.Felix$1.serviceChanged(Felix.java:622)
org.apache.felix.framework.ServiceRegistry.fireServiceChanged(ServiceReg
istry.java:576)
org.apache.felix.framework.ServiceRegistry.registerService(ServiceRegist
ry.java:86)
org.apache.felix.framework.Felix.registerService(Felix.java:2569)
org.apache.felix.framework.BundleContextImpl.registerService(BundleConte
xtImpl.java:252)
org.apache.cxf.dosgi.dsw.Activator.start(Activator.java:78)
org.apache.felix.framework.util.SecureAction.startActivator(SecureAction
.java:589)
org.apache.felix.framework.Felix.startBundle(Felix.java:1461)
org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:984)
org.apache.felix.framework.StartLevelImpl.run(StartLevelImpl.java:263)
java.lang.Thread.run(Unknown Source)
[2]
Name: Thread-4
State: BLOCKED on
org.apache.cxf.dosgi.dsw.hooks.cxffindlistenerh...@1a0283e owned by:
FelixStartLevel
Total blocked: 122 Total waited: 114
Stack trace:
org.apache.cxf.dosgi.dsw.hooks.AbstractClientHook.lookupDiscoveryService
(AbstractClientHook.java:201)
org.apache.cxf.dosgi.dsw.hooks.CxfFindListenerHook.find(CxfFindListenerH
ook.java:95)
org.apache.felix.framework.Felix.getServiceReferences(Felix.java:2642)
org.apache.felix.framework.Felix.getAllowedServiceReferences(Felix.java:
2672)
org.apache.felix.framework.BundleContextImpl.getServiceReferences(Bundle
ContextImpl.java:310)
org.apache.felix.eventadmin.impl.handler.BlacklistingHandlerTasks.create
HandlerTasks(BlacklistingHandlerTasks.java:114)
org.apache.felix.eventadmin.impl.EventAdminImpl.postEvent(EventAdminImpl
.java:87)
org.apache.felix.eventadmin.impl.adapter.LogEventAdapter$1.logged(LogEve
ntAdapter.java:285)
org.apache.felix.log.LogListenerThread.run(LogListenerThread.java:113)
- locked java.util.vec...@4478fe
- locked java.util.st...@39f16f
Now, after logging in using a remote shell (I use the
remote shell service), and requesting the runtime state using the
'ps' command, I get an extra deadlock:
[3]
Name: telnetconsole.shell remote=/127.0.0.1:1898
State: BLOCKED on
org.apache.cxf.dosgi.dsw.hooks.cxffindlistenerh...@1a0283e owned by:
FelixStartLevel
Total blocked: 1 Total waited: 0
Stack trace:
org.apache.cxf.dosgi.dsw.hooks.AbstractClientHook.lookupDiscoveryService
(AbstractClientHook.java:201)
org.apache.cxf.dosgi.dsw.hooks.CxfFindListenerHook.find(CxfFindListenerH
ook.java:95)
org.apache.felix.framework.Felix.getServiceReferences(Felix.java:2642)
org.apache.felix.framework.Felix.getAllowedServiceReferences(Felix.java:
2672)
org.apache.felix.framework.BundleContextImpl.getServiceReferences(Bundle
ContextImpl.java:310)
org.apache.felix.framework.BundleContextImpl.getServiceReference(BundleC
ontextImpl.java:261)
org.apache.felix.shell.impl.PsCommandImpl.execute(PsCommandImpl.java:58)
org.apache.felix.shell.impl.Activator$ShellServiceImpl.executeCommand(Ac
tivator.java:291)
- locked
org.apache.felix.shell.impl.activator$shellservicei...@438e1e
org.apache.felix.shell.remote.Shell.run(Shell.java:109)
java.lang.Thread.run(Unknown Source)
So I had a look at the code for the AbstractClientHook,
and pinned down where the deadlock is...
(red area is where the deadlock occurs).
protected synchronized void
lookupDiscoveryService(String interfaceName, String filterValue) {
LOG.info("lookup discovery service: interface: "
+ interfaceName
+ " filter: " + filterValue);
boolean change = false;
if (interfaceName != null) {
change |= append(trackerProperties,
INTERFACE_MATCH_CRITERIA,
interfaceName);
}
if (filterValue != null) {
change |= append(trackerProperties,
FILTER_MATCH_CRITERIA,
filterValue);
}
if (change) {
trackerRegistration.setProperties(trackerProperties);
}
}
@SuppressWarnings("unchecked")
private boolean append(Dictionary properties, String
key, String additional) {
Collection existing =
(Collection)properties.get(key);
if (existing == null) {
existing = new ArrayList<String>();
properties.put(key, existing);
}
if (!existing.contains(additional)) {
existing.add(additional);
return true;
} else {
return false;
}
}
Now the issue is - how is this deadlock occurring, and
how can it be avoided - is this an issue to do with
synchronized on the method? Is the LOG object not
threadsafe?
The LOG object is defined at the start of the
AbstractClientHook class,
public class AbstractClientHook extends
AbstractHook {
private static final Logger LOG =
Logger.getLogger(AbstractClientHook.class.getName());
Anyone have any ideas on this?
TIA, Chris
