Return-Path: X-Original-To: apmail-karaf-issues-archive@minotaur.apache.org Delivered-To: apmail-karaf-issues-archive@minotaur.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 4DA1C181DB for ; Wed, 23 Sep 2015 11:06:05 +0000 (UTC) Received: (qmail 91246 invoked by uid 500); 23 Sep 2015 11:06:05 -0000 Delivered-To: apmail-karaf-issues-archive@karaf.apache.org Received: (qmail 91218 invoked by uid 500); 23 Sep 2015 11:06:05 -0000 Mailing-List: contact issues-help@karaf.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@karaf.apache.org Delivered-To: mailing list issues@karaf.apache.org Received: (qmail 91205 invoked by uid 99); 23 Sep 2015 11:06:05 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 23 Sep 2015 11:06:05 +0000 Date: Wed, 23 Sep 2015 11:06:05 +0000 (UTC) From: =?utf-8?Q?Jean-Baptiste_Onofr=C3=A9_=28JIRA=29?= To: issues@karaf.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Resolved] (KARAF-3941) Deadlock when starting Karaf 3.0.4 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/KARAF-3941?page=3Dcom.atlassia= n.jira.plugin.system.issuetabpanels:all-tabpanel ] Jean-Baptiste Onofr=C3=A9 resolved KARAF-3941. ----------------------------------------- Resolution: Cannot Reproduce I'm not able to reproduce this issue. > 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 > Assignee: Jean-Baptiste Onofr=C3=A9 > Priority: Critical > > When upgrading my project from Karaf 3.0.3 to 3.0.4, starting up Karaf re= sults in an infinite hang. At first I thought this was a problem with integ= ration tests or pax exam, but then recreated it on standalone Karaf instanc= e. > It turns out that this is indeed a deadlock, between the "Refresh Package= s" and "Start Level Event Dispatcher" threads (thread dump below). > Also, a bit before that in the logs there was a FileNotFoundException whe= n it doesn't find /etc/overrides.properties. Putting an empty file there wo= rks around the issue. From the stack trace (below) it looks like it is rela= ted to the deadlock. > Also note that when comparing logs between 3.0.3 and 3.0.4, there is no b= undle 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 (whi= ch can potentially also be triggered by other exceptions other than the FNF= E - perhaps a lock isn't being released in a finally block or something lik= e that - this may or may not also be an issue in 3.0.3), the FNFE (if the f= ile 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: > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D > "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: > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D > "Refresh Packages": > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy= (BlueprintContainerImpl.java:850) > =09- waiting to lock <0x00000000a197afb8> (a java.util.concurrent.atomic.= AtomicBoolean) > =09at org.apache.aries.blueprint.container.BlueprintExtender$3.run(Bluepr= intExtender.java:319) > =09at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:= 511) > =09at java.util.concurrent.FutureTask.run(FutureTask.java:266) > =09at org.apache.aries.blueprint.container.BlueprintExtender.destroyConta= iner(BlueprintExtender.java:340) > =09at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBund= le(BlueprintExtender.java:236) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= customizerModified(BundleHookBundleTracker.java:500) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= customizerModified(BundleHookBundleTracker.java:433) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Abstract= Tracked.track(BundleHookBundleTracker.java:725) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= bundleChanged(BundleHookBundleTracker.java:463) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEv= entHook.event(BundleHookBundleTracker.java:422) > =09at org.eclipse.osgi.framework.internal.core.Framework$10.call(Framewor= k.java:1605) > =09at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHoo= kPrivileged(ServiceRegistry.java:1239) > =09at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHoo= ksPrivileged(ServiceRegistry.java:1222) > =09at org.eclipse.osgi.framework.internal.core.Framework.notifyEventHooks= Privileged(Framework.java:1602) > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= ntPrivileged(Framework.java:1557) > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= nt(Framework.java:1504) > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= nt(Framework.java:1499) > =09at org.eclipse.osgi.framework.internal.core.BundleHost.stopWorker(Bund= leHost.java:506) > =09at org.eclipse.osgi.framework.internal.core.AbstractBundle.suspend(Abs= tractBundle.java:566) > =09at org.eclipse.osgi.framework.internal.core.Framework.suspendBundle(Fr= amework.java:1206) > =09at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.suspendBu= ndle(PackageAdminImpl.java:326) > =09at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.processDe= lta(PackageAdminImpl.java:467) > =09at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.doResolve= Bundles(PackageAdminImpl.java:251) > =09- locked <0x00000000a1bc61b0> (a org.eclipse.osgi.framework.internal.c= ore.PackageAdminImpl) > =09at org.eclipse.osgi.framework.internal.core.PackageAdminImpl$1.run(Pac= kageAdminImpl.java:174) > =09at java.lang.Thread.run(Thread.java:745) > "Start Level Event Dispatcher": > =09at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.doResolve= Bundles(PackageAdminImpl.java:207) > =09- waiting to lock <0x00000000a1bc61b0> (a org.eclipse.osgi.framework.i= nternal.core.PackageAdminImpl) > =09at org.eclipse.osgi.framework.internal.core.PackageAdminImpl.resolveBu= ndles(PackageAdminImpl.java:192) > =09at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(Bun= dleHost.java:322) > =09at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(Abstr= actBundle.java:300) > =09at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(Abstr= actBundle.java:292) > =09at org.apache.karaf.features.internal.FeaturesServiceImpl.startBundle(= FeaturesServiceImpl.java:518) > =09at org.apache.karaf.features.internal.FeaturesServiceImpl.installFeatu= res(FeaturesServiceImpl.java:476) > =09at org.apache.karaf.features.internal.BootFeaturesInstaller.installBoo= tFeatures(BootFeaturesInstaller.java:92) > =09at org.apache.karaf.features.internal.BootFeaturesInstaller.start(Boot= FeaturesInstaller.java:76) > =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImp= l.java:62) > =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcc= essorImpl.java:43) > =09at java.lang.reflect.Method.invoke(Method.java:497) > =09at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionU= tils.java:297) > =09at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.j= ava:958) > =09at org.apache.aries.blueprint.container.BeanRecipe.runBeanProcInit(Bea= nRecipe.java:712) > =09at org.apache.aries.blueprint.container.BeanRecipe.internalCreate2(Bea= nRecipe.java:824) > =09at org.apache.aries.blueprint.container.BeanRecipe.internalCreate(Bean= Recipe.java:787) > =09at org.apache.aries.blueprint.di.AbstractRecipe$1.call(AbstractRecipe.= java:79) > =09at java.util.concurrent.FutureTask.run(FutureTask.java:266) > =09at org.apache.aries.blueprint.di.AbstractRecipe.create(AbstractRecipe.= java:88) > =09at org.apache.aries.blueprint.container.BlueprintRepository.createInst= ances(BlueprintRepository.java:245) > =09at org.apache.aries.blueprint.container.BlueprintRepository.createAll(= BlueprintRepository.java:183) > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.instant= iateEagerComponents(BlueprintContainerImpl.java:682) > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(B= lueprintContainerImpl.java:377) > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.run(Blu= eprintContainerImpl.java:269) > =09- locked <0x00000000a197afb8> (a java.util.concurrent.atomic.AtomicBoo= lean) > =09at org.apache.aries.blueprint.container.BlueprintExtender.createContai= ner(BlueprintExtender.java:294) > =09at org.apache.aries.blueprint.container.BlueprintExtender.createContai= ner(BlueprintExtender.java:263) > =09at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBund= le(BlueprintExtender.java:253) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= customizerModified(BundleHookBundleTracker.java:500) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= customizerModified(BundleHookBundleTracker.java:433) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Abstract= Tracked.track(BundleHookBundleTracker.java:725) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= bundleChanged(BundleHookBundleTracker.java:463) > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEv= entHook.event(BundleHookBundleTracker.java:422) > =09at org.eclipse.osgi.framework.internal.core.Framework$10.call(Framewor= k.java:1605) > =09at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHoo= kPrivileged(ServiceRegistry.java:1239) > =09at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHoo= ksPrivileged(ServiceRegistry.java:1222) > =09at org.eclipse.osgi.framework.internal.core.Framework.notifyEventHooks= Privileged(Framework.java:1602) > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= ntPrivileged(Framework.java:1557) > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= nt(Framework.java:1504) > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= nt(Framework.java:1499) > =09at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(Bun= dleHost.java:391) > =09at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(Abst= ractBundle.java:390) > =09at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Fra= mework.java:1176) > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBu= ndles(StartLevelManager.java:559) > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBu= ndles(StartLevelManager.java:544) > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(= StartLevelManager.java:457) > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetSta= rtLevel(StartLevelManager.java:243) > =09- locked <0x00000000a1bd3fd0> (a java.lang.Object) > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatch= Event(StartLevelManager.java:438) > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatch= Event(StartLevelManager.java:1) > =09at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(Even= tManager.java:230) > =09at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(Ev= entManager.java:340) > Found 1 deadlock. > {quote} > and the exception stack trace: > {quote} > java.io.FileNotFoundException: /tmp/apache-karaf-3.0.4/etc/overrides.prop= erties (No such file or directory) > =09at java.io.FileInputStream.open0(Native Method)[:1.8.0_60] > =09at java.io.FileInputStream.open(FileInputStream.java:195)[:1.8.0_60] > =09at java.io.FileInputStream.(FileInputStream.java:138)[:1.8.0_60] > =09at java.io.FileInputStream.(FileInputStream.java:93)[:1.8.0_60] > =09at sun.net.www.protocol.file.FileURLConnection.connect(FileURLConnecti= on.java:90)[:1.8.0_60] > =09at sun.net.www.protocol.file.FileURLConnection.getInputStream(FileURLC= onnection.java:188)[:1.8.0_60] > =09at java.net.URL.openStream(URL.java:1038)[:1.8.0_60] > =09at org.apache.karaf.features.internal.Overrides.loadOverrides(Override= s.java:165) > =09at org.apache.karaf.features.internal.Overrides.override(Overrides.jav= a:74) > =09at org.apache.karaf.features.internal.FeaturesServiceImpl.doInstallFea= ture(FeaturesServiceImpl.java:571) > =09at org.apache.karaf.features.internal.FeaturesServiceImpl.installFeatu= res(FeaturesServiceImpl.java:436) > =09at org.apache.karaf.features.internal.BootFeaturesInstaller.installBoo= tFeatures(BootFeaturesInstaller.java:92) > =09at org.apache.karaf.features.internal.BootFeaturesInstaller.start(Boot= FeaturesInstaller.java:76) > =09at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_= 60] > =09at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImp= l.java:62)[:1.8.0_60] > =09at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcc= essorImpl.java:43)[:1.8.0_60] > =09at java.lang.reflect.Method.invoke(Method.java:497)[:1.8.0_60] > =09at org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionU= tils.java:297)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.j= ava:958)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BeanRecipe.runBeanProcInit(Bea= nRecipe.java:712)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BeanRecipe.internalCreate2(Bea= nRecipe.java:824)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BeanRecipe.internalCreate(Bean= Recipe.java:787)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.di.AbstractRecipe$1.call(AbstractRecipe.= java:79)[15:org.apache.aries.blueprint.core:1.4.3] > =09at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_60] > =09at org.apache.aries.blueprint.di.AbstractRecipe.create(AbstractRecipe.= java:88)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintRepository.createInst= ances(BlueprintRepository.java:245)[15:org.apache.aries.blueprint.core:1.4.= 3] > =09at org.apache.aries.blueprint.container.BlueprintRepository.createAll(= BlueprintRepository.java:183)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.instant= iateEagerComponents(BlueprintContainerImpl.java:682)[15:org.apache.aries.bl= ueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(B= lueprintContainerImpl.java:377)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintContainerImpl.run(Blu= eprintContainerImpl.java:269)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintExtender.createContai= ner(BlueprintExtender.java:294)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintExtender.createContai= ner(BlueprintExtender.java:263)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBund= le(BlueprintExtender.java:253)[15:org.apache.aries.blueprint.core:1.4.3] > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= customizerModified(BundleHookBundleTracker.java:500)[9:org.apache.aries.uti= l:1.1.0] > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= customizerModified(BundleHookBundleTracker.java:433)[9:org.apache.aries.uti= l:1.1.0] > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Abstract= Tracked.track(BundleHookBundleTracker.java:725)[9:org.apache.aries.util:1.1= .0] > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.= bundleChanged(BundleHookBundleTracker.java:463)[9:org.apache.aries.util:1.1= .0] > =09at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEv= entHook.event(BundleHookBundleTracker.java:422)[9:org.apache.aries.util:1.1= .0] > =09at org.eclipse.osgi.framework.internal.core.Framework$10.call(Framewor= k.java:1605)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHoo= kPrivileged(ServiceRegistry.java:1239)[org.eclipse.osgi-3.8.2.v20130124-134= 944.jar:] > =09at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.notifyHoo= ksPrivileged(ServiceRegistry.java:1222)[org.eclipse.osgi-3.8.2.v20130124-13= 4944.jar:] > =09at org.eclipse.osgi.framework.internal.core.Framework.notifyEventHooks= Privileged(Framework.java:1602)[org.eclipse.osgi-3.8.2.v20130124-134944.jar= :] > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= ntPrivileged(Framework.java:1557)[org.eclipse.osgi-3.8.2.v20130124-134944.j= ar:] > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= nt(Framework.java:1504)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEve= nt(Framework.java:1499)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(Bun= dleHost.java:391)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(Abst= ractBundle.java:390)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Fra= mework.java:1176)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBu= ndles(StartLevelManager.java:559)[org.eclipse.osgi-3.8.2.v20130124-134944.j= ar:] > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBu= ndles(StartLevelManager.java:544)[org.eclipse.osgi-3.8.2.v20130124-134944.j= ar:] > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(= StartLevelManager.java:457)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetSta= rtLevel(StartLevelManager.java:243)[org.eclipse.osgi-3.8.2.v20130124-134944= .jar:] > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatch= Event(StartLevelManager.java:438)[org.eclipse.osgi-3.8.2.v20130124-134944.j= ar:] > =09at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatch= Event(StartLevelManager.java:1)[org.eclipse.osgi-3.8.2.v20130124-134944.jar= :] > =09at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(Even= tManager.java:230)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > =09at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(Ev= entManager.java:340)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:] > {quote} -- This message was sent by Atlassian JIRA (v6.3.4#6332)