Investigating it further I found this line of code in the Apache Aries Project which seems to cause the timeout after 60 seconds, but that has always been there. https://github.com/apache/aries/blob/trunk/blueprint/blueprint-core/src/main/java/org/apache/aries/blueprint/container/BlueprintEventDispatcher.java#L193
Again maybe this is not an Apache Karaf issue, rather a Apache Camel issue but i’m not quite sure. So what seems to be happening is that the 60 seconds timeout, interrupts the 300 second timeout of the graceful shutdown procedure of the camel xml blueprint bundle. Any thoughts on this, and how to make sure the 300 second timeout of camel is not being interrupted? — Joery On 2 Jun 2018, 22:17 +0200, Joery Vreijsen <[email protected]>, wrote: > Hi there! > > I’m running into a weird issue regarding some timeouts when uninstalling a > CamelContext in Karaf 4.2.0. > Due to the fact that i’m not entirely sure if this is a Camel or Karaf issue, > but the exception is thrown from inside Karaf i’m going to try it here first. > > I am installing a Camel Context in Karaf using a blueprint.xml. Say a route > in this context has a syntax error in it, and when it’s still running i’m > trying to uninstall the bundle in Karaf. > The result is correct, i get the inflight message from Camel with the note > saying it’s going to timeout in 5 minutes (300 seconds): > > [Camel (context-1) thread #1 - ShutdownTask] Waiting as there are still 3 > inflight and pending exchanges to complete, timeout in 295 seconds. Inflights > per route: [route-3 = 1, route-2 = 1, route-1 = 1] > [Camel (context-1) thread #1 - ShutdownTask] There are 2 inflight exchanges: > InflightExchange: [exchangeId=ID-mac-local-1527969270260-1-1, > fromRouteId=route-1, routeId=route-2, nodeId=split2, elapsed=0, > duration=71634] > InflightExchange: [exchangeId=ID-mac-local-1527969270260-1-3, > fromRouteId=route-1, routeId=route-3, nodeId=to6, elapsed=0, duration=71634] > > But after exactly one minute (consistently) the graceful shutdown procedure > of camel is interrupted and the following appears in the logs: > > WARN [Blueprint Event Dispatcher: 1] Timeout occurred during graceful > shutdown. Forcing the routes to be shutdown now. Notice: some resources may > still be running as graceful shutdown did not complete successfully. > WARN [pipe-bundle:uninstall 110] Listener timed out, will be ignored > java.util.concurrent.TimeoutException: null > at > java.util.concurrent.AbstractExecutorService.doInvokeAny(AbstractExecutorService.java:184) > ~[?:?] > at > java.util.concurrent.AbstractExecutorService.invokeAny(AbstractExecutorService.java:225) > ~[?:?] > at > org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper$4.call(ScheduledExecutorServiceWrapper.java:182) > ~[45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper$15.call(ScheduledExecutorServiceWrapper.java:443) > ~[45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.utils.threading.RWLock.runReadOperation(RWLock.java:33) > ~[45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper.runUnlessShutdown(ScheduledExecutorServiceWrapper.java:440) > ~[45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper.invokeAny(ScheduledExecutorServiceWrapper.java:177) > ~[45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.container.BlueprintEventDispatcher.callListener(BlueprintEventDispatcher.java:188) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.container.BlueprintEventDispatcher.callListeners(BlueprintEventDispatcher.java:178) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.container.BlueprintEventDispatcher.blueprintEvent(BlueprintEventDispatcher.java:133) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:888) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:324) > [45:org.apache.aries.blueprint.core:1.9.0] > 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:345) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:237) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422) > [45:org.apache.aries.blueprint.core:1.9.0] > at > org.apache.felix.framework.util.SecureAction.invokeBundleEventHook(SecureAction.java:1179) > [?:?] > at > org.apache.felix.framework.EventDispatcher.createWhitelistFromHooks(EventDispatcher.java:730) > [?:?] > at > org.apache.felix.framework.EventDispatcher.fireBundleEvent(EventDispatcher.java:485) > [?:?] > at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4579) [?:?] > at org.apache.felix.framework.Felix.stopBundle(Felix.java:2626) [?:?] > at org.apache.felix.framework.Felix.uninstallBundle(Felix.java:2750) [?:?] > at org.apache.felix.framework.BundleImpl.uninstall(BundleImpl.java:1055) [?:?] > at > org.apache.karaf.bundle.command.Uninstall.executeOnBundle(Uninstall.java:34) > [15:org.apache.karaf.bundle.core:4.2.0] > at > org.apache.karaf.bundle.command.BundlesCommand.doExecute(BundlesCommand.java:65) > [15:org.apache.karaf.bundle.core:4.2.0] > at > org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:55) > [15:org.apache.karaf.bundle.core:4.2.0] > at > org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:84) > [33:org.apache.karaf.shell.core:4.2.0] > at > org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:68) > [33:org.apache.karaf.shell.core:4.2.0] > at > org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:86) > [33:org.apache.karaf.shell.core:4.2.0] > at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:571) > [33:org.apache.karaf.shell.core:4.2.0] > at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:497) > [33:org.apache.karaf.shell.core:4.2.0] > at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:386) > [33:org.apache.karaf.shell.core:4.2.0] > at org.apache.felix.gogo.runtime.Pipe.doCall(Pipe.java:417) > [33:org.apache.karaf.shell.core:4.2.0] > at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:229) > [33:org.apache.karaf.shell.core:4.2.0] > at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:59) > [33:org.apache.karaf.shell.core:4.2.0] > at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?] > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) > [?:?] > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) > [?:?] > at java.lang.Thread.run(Thread.java:745) [?:?] > > 21:56:12.711 WARN [Camel (context-1) thread #1 - ShutdownTask] Interrupted > while waiting during graceful shutdown, will force shutdown now. > > I’m curious to why this exception occurs after exactly one minute, and the > Camel Graceful Shutdown Timeout as specified is interrupted. > > I reproduced this on a clean Karaf 4.2.0 build with only the Camel feature > installed to run the Camel Context. > > Any insight on why this might be happening? > > — > > Greetings, > > - Joery
