Amichai Rothman created KARAF-3941:
--------------------------------------
Summary: Deadlock when starting Karaf 3.0.4
Key: KARAF-3941
URL: https://issues.apache.org/jira/browse/KARAF-3941
Project: Karaf
Issue Type: Bug
Components: karaf-core
Affects Versions: 3.0.4
Environment: Oracle JDK 8u60 64-bit Linux
Reporter: Amichai Rothman
Priority: Critical
When upgrading my project from Karaf 3.0.3 to 3.0.4, starting up Karaf results
in an infinite hang. At first I thought this was a problem with integration
tests or pax exam, but then recreated it on standalone Karaf instance.
It turns out that this is indeed a deadlock, between the "Refresh Packages" and
"Start Level Event Dispatcher" threads (thread dump below).
Also, a bit before that in the logs there was a FileNotFoundException when it
doesn't find /etc/overrides.properties. Putting an empty file there works
around the issue. From the stack trace (below) it looks like it is related to
the deadlock.
Also note that when comparing logs between 3.0.3 and 3.0.4, there is no bundle
refreshing going on at this point of Karaf 3.0.3 startup, whereas in 3.0.4
there is, and that triggers the deadlock.
In summary, there is one or more bugs here: the deadlock that occurs (which can
potentially also be triggered by other exceptions other than the FNFE - perhaps
a lock isn't being released in a finally block or something like that - this
may or may not also be an issue in 3.0.3), the FNFE (if the file is optional it
shouldn't be throwing an exception and/or the exception should be better
handled), and the bundle refresh that's occurring in 3.0.4 and not 3.0.3 (may
be non-harmful by itself, but probably unnecessary and bad for startup
performance anyway).
The deadlock thread dump:
{quote}
Found one Java-level deadlock:
=============================
"Refresh Packages":
waiting to lock monitor 0x00007f051c007588 (object 0x00000000a197afb8, a
java.util.concurrent.atomic.AtomicBoolean),
which is held by "Start Level Event Dispatcher"
"Start Level Event Dispatcher":
waiting to lock monitor 0x00007f051c007008 (object 0x00000000a1bc61b0, a
org.eclipse.osgi.framework.internal.core.PackageAdminImpl),
which is held by "Refresh Packages"
Java stack information for the threads listed above:
===================================================
"Refresh Packages":
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:850)
- waiting to lock <0x00000000a197afb8> (a
java.util.concurrent.atomic.AtomicBoolean)
at
org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:319)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
org.apache.aries.blueprint.container.BlueprintExtender.destroyContainer(BlueprintExtender.java:340)
at
org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:236)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422)
at
org.eclipse.osgi.framework.internal.core.Framework$10.call(Framework.java:1605)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHookPrivileged(ServiceRegistry.java:1239)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHooksPrivileged(ServiceRegistry.java:1222)
at
org.eclipse.osgi.framework.internal.core.Framework.notifyEventHooksPrivileged(Framework.java:1602)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1557)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1504)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1499)
at
org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(BundleHost.java:506)
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.suspend(AbstractBundle.java:566)
at
org.eclipse.osgi.framework.internal.core.Framework.suspendBundle(Framework.java:1206)
at
org.eclipse.osgi.framework.internal.core.PackageAdminImpl.suspendBundle(PackageAdminImpl.java:326)
at
org.eclipse.osgi.framework.internal.core.PackageAdminImpl.processDelta(PackageAdminImpl.java:467)
at
org.eclipse.osgi.framework.internal.core.PackageAdminImpl.doResolveBundles(PackageAdminImpl.java:251)
- locked <0x00000000a1bc61b0> (a
org.eclipse.osgi.framework.internal.core.PackageAdminImpl)
at
org.eclipse.osgi.framework.internal.core.PackageAdminImpl$1.run(PackageAdminImpl.java:174)
at java.lang.Thread.run(Thread.java:745)
"Start Level Event Dispatcher":
at
org.eclipse.osgi.framework.internal.core.PackageAdminImpl.doResolveBundles(PackageAdminImpl.java:207)
- waiting to lock <0x00000000a1bc61b0> (a
org.eclipse.osgi.framework.internal.core.PackageAdminImpl)
at
org.eclipse.osgi.framework.internal.core.PackageAdminImpl.resolveBundles(PackageAdminImpl.java:192)
at
org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:322)
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:300)
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:292)
at
org.apache.karaf.features.internal.FeaturesServiceImpl.startBundle(FeaturesServiceImpl.java:518)
at
org.apache.karaf.features.internal.FeaturesServiceImpl.installFeatures(FeaturesServiceImpl.java:476)
at
org.apache.karaf.features.internal.BootFeaturesInstaller.installBootFeatures(BootFeaturesInstaller.java:92)
at
org.apache.karaf.features.internal.BootFeaturesInstaller.start(BootFeaturesInstaller.java:76)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:297)
at
org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:958)
at
org.apache.aries.blueprint.container.BeanRecipe.runBeanProcInit(BeanRecipe.java:712)
at
org.apache.aries.blueprint.container.BeanRecipe.internalCreate2(BeanRecipe.java:824)
at
org.apache.aries.blueprint.container.BeanRecipe.internalCreate(BeanRecipe.java:787)
at
org.apache.aries.blueprint.di.AbstractRecipe$1.call(AbstractRecipe.java:79)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
org.apache.aries.blueprint.di.AbstractRecipe.create(AbstractRecipe.java:88)
at
org.apache.aries.blueprint.container.BlueprintRepository.createInstances(BlueprintRepository.java:245)
at
org.apache.aries.blueprint.container.BlueprintRepository.createAll(BlueprintRepository.java:183)
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.instantiateEagerComponents(BlueprintContainerImpl.java:682)
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(BlueprintContainerImpl.java:377)
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.run(BlueprintContainerImpl.java:269)
- locked <0x00000000a197afb8> (a
java.util.concurrent.atomic.AtomicBoolean)
at
org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:294)
at
org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:263)
at
org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:253)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422)
at
org.eclipse.osgi.framework.internal.core.Framework$10.call(Framework.java:1605)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHookPrivileged(ServiceRegistry.java:1239)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHooksPrivileged(ServiceRegistry.java:1222)
at
org.eclipse.osgi.framework.internal.core.Framework.notifyEventHooksPrivileged(Framework.java:1602)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1557)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1504)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1499)
at
org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:391)
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:390)
at
org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1176)
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:559)
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:544)
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:457)
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)
- locked <0x00000000a1bd3fd0> (a java.lang.Object)
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:438)
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:1)
at
org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
at
org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)
Found 1 deadlock.
{quote}
and the exception stack trace:
{quote}
java.io.FileNotFoundException: /tmp/apache-karaf-3.0.4/etc/overrides.properties
(No such file or directory)
at java.io.FileInputStream.open0(Native Method)[:1.8.0_60]
at java.io.FileInputStream.open(FileInputStream.java:195)[:1.8.0_60]
at java.io.FileInputStream.<init>(FileInputStream.java:138)[:1.8.0_60]
at java.io.FileInputStream.<init>(FileInputStream.java:93)[:1.8.0_60]
at
sun.net.www.protocol.file.FileURLConnection.connect(FileURLConnection.java:90)[:1.8.0_60]
at
sun.net.www.protocol.file.FileURLConnection.getInputStream(FileURLConnection.java:188)[:1.8.0_60]
at java.net.URL.openStream(URL.java:1038)[:1.8.0_60]
at
org.apache.karaf.features.internal.Overrides.loadOverrides(Overrides.java:165)
at
org.apache.karaf.features.internal.Overrides.override(Overrides.java:74)
at
org.apache.karaf.features.internal.FeaturesServiceImpl.doInstallFeature(FeaturesServiceImpl.java:571)
at
org.apache.karaf.features.internal.FeaturesServiceImpl.installFeatures(FeaturesServiceImpl.java:436)
at
org.apache.karaf.features.internal.BootFeaturesInstaller.installBootFeatures(BootFeaturesInstaller.java:92)
at
org.apache.karaf.features.internal.BootFeaturesInstaller.start(BootFeaturesInstaller.java:76)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)[:1.8.0_60]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_60]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_60]
at java.lang.reflect.Method.invoke(Method.java:497)[:1.8.0_60]
at
org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:297)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:958)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BeanRecipe.runBeanProcInit(BeanRecipe.java:712)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BeanRecipe.internalCreate2(BeanRecipe.java:824)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BeanRecipe.internalCreate(BeanRecipe.java:787)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.di.AbstractRecipe$1.call(AbstractRecipe.java:79)[15:org.apache.aries.blueprint.core:1.4.3]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_60]
at
org.apache.aries.blueprint.di.AbstractRecipe.create(AbstractRecipe.java:88)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintRepository.createInstances(BlueprintRepository.java:245)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintRepository.createAll(BlueprintRepository.java:183)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.instantiateEagerComponents(BlueprintContainerImpl.java:682)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(BlueprintContainerImpl.java:377)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.run(BlueprintContainerImpl.java:269)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:294)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:263)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:253)[15:org.apache.aries.blueprint.core:1.4.3]
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500)[9:org.apache.aries.util:1.1.0]
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433)[9:org.apache.aries.util:1.1.0]
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725)[9:org.apache.aries.util:1.1.0]
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463)[9:org.apache.aries.util:1.1.0]
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422)[9:org.apache.aries.util:1.1.0]
at
org.eclipse.osgi.framework.internal.core.Framework$10.call(Framework.java:1605)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHookPrivileged(ServiceRegistry.java:1239)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHooksPrivileged(ServiceRegistry.java:1222)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.Framework.notifyEventHooksPrivileged(Framework.java:1602)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1557)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1504)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1499)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:391)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:390)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1176)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:559)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:544)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:457)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:438)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:1)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at
org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
{quote}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
