[
https://issues.apache.org/jira/browse/FELIX-3067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13908140#comment-13908140
]
metatech edited comment on FELIX-3067 at 2/21/14 10:12 AM:
-----------------------------------------------------------
With ServiceMix 4.5.3 (containing Felix 3.2.2), here are the 2 threads involved
in the deadlock when trying to acquire the Felix global lock together with the
"logger" lock. Check for the 4 -----> below.
{code}
"FelixPackageAdmin" daemon prio=6 tid=0x0000000008df2800 nid=0x2f6c waiting for
monitor entry [0x00000000098ae000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock <0x00000000c02d4010> (a
org.apache.log4j.sift.MDCSiftingAppender)
-----> Trying to acquire log lock
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at
org.ops4j.pax.logging.service.internal.PaxLoggerImpl.error(PaxLoggerImpl.java:159)
at
org.ops4j.pax.logging.internal.TrackingLogger.error(TrackingLogger.java:96)
at
org.apache.commons.logging.internal.JclLogger.error(JclLogger.java:164)
at
org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution.execute(RunnableTimedExecution.java:109)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener.maybeCloseApplicationContextFor(ContextLoaderListener.java:798)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener$ContextBundleListener.handleEvent(ContextLoaderListener.java:242)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener$BaseListener.bundleChanged(ContextLoaderListener.java:172)
at
org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)
at
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)
at
org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)
at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3879)
at org.apache.felix.framework.Felix.stopBundle(Felix.java:2268)
at org.apache.felix.framework.Felix$RefreshHelper.stop(Felix.java:4668)
-----> Global lock acquired
at org.apache.felix.framework.Felix.refreshPackages(Felix.java:3699)
at
org.apache.felix.framework.PackageAdminImpl.run(PackageAdminImpl.java:365)
at java.lang.Thread.run(Thread.java:662)
"Timer-2" daemon prio=6 tid=0x0000000010202000 nid=0x23cc in Object.wait()
[0x000000001352e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
-----> Trying to acquire global lock
at org.apache.felix.framework.Felix.acquireGlobalLock(Felix.java:4995)
- locked <0x00000000c082b910> (a [Ljava.lang.Object;)
at org.apache.felix.framework.Felix.access$600(Felix.java:79)
at
org.apache.felix.framework.Felix$StatefulResolver.resolve(Felix.java:4177)
at
org.apache.felix.framework.ModuleImpl.searchDynamicImports(ModuleImpl.java:1448)
at
org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:759)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at
org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at
org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at
org.apache.felix.framework.resolver.WireModuleImpl.getClass(WireModuleImpl.java:97)
at
org.apache.felix.framework.ModuleImpl.searchImports(ModuleImpl.java:1426)
at
org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:747)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at
org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at
org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at org.apache.felix.framework.Felix.loadBundleClass(Felix.java:1654)
at org.apache.felix.framework.BundleImpl.loadClass(BundleImpl.java:909)
at
org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
at
org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.ops4j.pax.logging.util.OsgiUtil.loadClass(OsgiUtil.java:99)
at
org.apache.log4j.OsgiThrowableRenderer.findClass(OsgiThrowableRenderer.java:221)
at
org.apache.log4j.OsgiThrowableRenderer.formatElement(OsgiThrowableRenderer.java:134)
at
org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:105)
at
org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:52)
at
org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:89)
- locked <0x00000000c482ac88> (a
org.apache.log4j.spi.ThrowableInformation)
at
org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
at
org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x00000000c02d6688> (a
org.apache.log4j.DailyRollingFileAppender)
at
org.apache.log4j.sift.MDCSiftingAppender.append(MDCSiftingAppender.java:80)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
-----> Log lock acquired
- locked <0x00000000c02d4010> (a
org.apache.log4j.sift.MDCSiftingAppender)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at
org.ops4j.pax.logging.service.internal.PaxLoggerImpl.warn(PaxLoggerImpl.java:151)
at
org.ops4j.pax.logging.internal.TrackingLogger.warn(TrackingLogger.java:91)
at
org.apache.commons.logging.internal.JclLogger.warn(JclLogger.java:151)
at
org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1010)
at
org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.doClose(AbstractOsgiBundleApplicationContext.java:197)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.access$501(AbstractDelegatedExecutionApplicationContext.java:69)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext$2.run(AbstractDelegatedExecutionApplicationContext.java:214)
at
org.springframework.osgi.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.normalClose(AbstractDelegatedExecutionApplicationContext.java:210)
at
org.springframework.osgi.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.close(DependencyWaiterApplicationContextExecutor.java:374)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.doClose(AbstractDelegatedExecutionApplicationContext.java:236)
at
org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:970)
- locked <0x00000000c2778310> (a java.lang.Object)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener$3.run(ContextLoaderListener.java:805)
at
org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution$MonitoredRunnable.run(RunnableTimedExecution.java:60)
at
org.springframework.scheduling.timer.DelegatingTimerTask.run(DelegatingTimerTask.java:70)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
{code}
was (Author: metatech):
With ServiceMix 4.5.3 (containing Felix 3.2.2), here are the 2 threads involved
in the deadlock when trying to acquire the Felix global lock together with the
"logger" lock. Check for the 4 -----> below.
{code}
"FelixPackageAdmin" daemon prio=6 tid=0x0000000008df2800 nid=0x2f6c waiting for
monitor entry [0x00000000098ae000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock <0x00000000c02d4010> (a
org.apache.log4j.sift.MDCSiftingAppender)
-----> Trying to acquire lock lock
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at
org.ops4j.pax.logging.service.internal.PaxLoggerImpl.error(PaxLoggerImpl.java:159)
at
org.ops4j.pax.logging.internal.TrackingLogger.error(TrackingLogger.java:96)
at
org.apache.commons.logging.internal.JclLogger.error(JclLogger.java:164)
at
org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution.execute(RunnableTimedExecution.java:109)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener.maybeCloseApplicationContextFor(ContextLoaderListener.java:798)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener$ContextBundleListener.handleEvent(ContextLoaderListener.java:242)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener$BaseListener.bundleChanged(ContextLoaderListener.java:172)
at
org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)
at
org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)
at
org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)
at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3879)
at org.apache.felix.framework.Felix.stopBundle(Felix.java:2268)
at org.apache.felix.framework.Felix$RefreshHelper.stop(Felix.java:4668)
-----> Global lock acquired
at org.apache.felix.framework.Felix.refreshPackages(Felix.java:3699)
at
org.apache.felix.framework.PackageAdminImpl.run(PackageAdminImpl.java:365)
at java.lang.Thread.run(Thread.java:662)
"Timer-2" daemon prio=6 tid=0x0000000010202000 nid=0x23cc in Object.wait()
[0x000000001352e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
-----> Trying to acquire global lock
at org.apache.felix.framework.Felix.acquireGlobalLock(Felix.java:4995)
- locked <0x00000000c082b910> (a [Ljava.lang.Object;)
at org.apache.felix.framework.Felix.access$600(Felix.java:79)
at
org.apache.felix.framework.Felix$StatefulResolver.resolve(Felix.java:4177)
at
org.apache.felix.framework.ModuleImpl.searchDynamicImports(ModuleImpl.java:1448)
at
org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:759)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at
org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at
org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at
org.apache.felix.framework.resolver.WireModuleImpl.getClass(WireModuleImpl.java:97)
at
org.apache.felix.framework.ModuleImpl.searchImports(ModuleImpl.java:1426)
at
org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:747)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at
org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at
org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at org.apache.felix.framework.Felix.loadBundleClass(Felix.java:1654)
at org.apache.felix.framework.BundleImpl.loadClass(BundleImpl.java:909)
at
org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
at
org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.ops4j.pax.logging.util.OsgiUtil.loadClass(OsgiUtil.java:99)
at
org.apache.log4j.OsgiThrowableRenderer.findClass(OsgiThrowableRenderer.java:221)
at
org.apache.log4j.OsgiThrowableRenderer.formatElement(OsgiThrowableRenderer.java:134)
at
org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:105)
at
org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:52)
at
org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:89)
- locked <0x00000000c482ac88> (a
org.apache.log4j.spi.ThrowableInformation)
at
org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
at
org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x00000000c02d6688> (a
org.apache.log4j.DailyRollingFileAppender)
at
org.apache.log4j.sift.MDCSiftingAppender.append(MDCSiftingAppender.java:80)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
-----> Log lock acquired
- locked <0x00000000c02d4010> (a
org.apache.log4j.sift.MDCSiftingAppender)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at
org.ops4j.pax.logging.service.internal.PaxLoggerImpl.warn(PaxLoggerImpl.java:151)
at
org.ops4j.pax.logging.internal.TrackingLogger.warn(TrackingLogger.java:91)
at
org.apache.commons.logging.internal.JclLogger.warn(JclLogger.java:151)
at
org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1010)
at
org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.doClose(AbstractOsgiBundleApplicationContext.java:197)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.access$501(AbstractDelegatedExecutionApplicationContext.java:69)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext$2.run(AbstractDelegatedExecutionApplicationContext.java:214)
at
org.springframework.osgi.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.normalClose(AbstractDelegatedExecutionApplicationContext.java:210)
at
org.springframework.osgi.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.close(DependencyWaiterApplicationContextExecutor.java:374)
at
org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.doClose(AbstractDelegatedExecutionApplicationContext.java:236)
at
org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:970)
- locked <0x00000000c2778310> (a java.lang.Object)
at
org.springframework.osgi.extender.internal.activator.ContextLoaderListener$3.run(ContextLoaderListener.java:805)
at
org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution$MonitoredRunnable.run(RunnableTimedExecution.java:60)
at
org.springframework.scheduling.timer.DelegatingTimerTask.run(DelegatingTimerTask.java:70)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
{code}
> Prevent Deadlock Situation in Felix.acquireGlobalLock
> -----------------------------------------------------
>
> Key: FELIX-3067
> URL: https://issues.apache.org/jira/browse/FELIX-3067
> Project: Felix
> Issue Type: Improvement
> Components: Framework
> Affects Versions: framework-3.0.7, framework-3.0.8, framework-3.0.9,
> framework-3.2.0, framework-3.2.1, fileinstall-3.1.10
> Reporter: Felix Meschberger
> Attachments: FELIX-3067-sling.patch, FELIX-3067.patch,
> threaddump-ise-deadlock.txt, threads_locked_by_camel_type_converter
>
>
> Every now and then we encounter deadlock situations which involve the
> Felix.acquireGlobalLock method. In our use case we have the following aspects
> which contribute to this:
> (a) The Apache Felix Declarative Services implementation stops components
> (and thus causes service unregistration) while the bundle lock is being held
> because this happens in a SynchronousBundleListener while handling the
> STOPPING bundle event. We have to do this to ensure the bundle is not really
> stopped yet to properly stop the bundle's components.
> (b) Implementing a special class loader which involves dynamically resolving
> packages which in turn uses the global lock
> (c) Eclipse Gemini Blueprint implementation which operates asynchronously
> (d) synchronization in application classes
> Often times, I would assume that we can self-heal such complex deadlck
> situations, if we let acquireGlobalLock time out. Looking at the calles of
> acquireGlobalLock there seems to already be provision to handle this case
> since acquireGlobalLock returns true only if the global lock has actually
> been acquired.
> This issue is kind of a companion to FELIX-3000 where deadlocks involve
> sending service registration events while holding the bundle lock.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)
