Details
Critical Description
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:
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.
and the exception stack trace:
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:]