Karaf 4.2.0: java.util.concurrent.TimeoutException: null

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Karaf 4.2.0: java.util.concurrent.TimeoutException: null

joeryv
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
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

joeryv
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.

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 <[hidden email]>, 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
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

jbonofre
In reply to this post by joeryv
Hi

do you use the default Camel graceful shutdown strategy or a custom one ?

Regards
JB

On 02/06/2018 22:17, Joery Vreijsen 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

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

joeryv
Hi!

Thanks for the quick response, yes I used the DefaultShutdownStrategy of Apache Camel 2.21.1.



Joery
On 3 Jun 2018, 17:24 +0200, Jean-Baptiste Onofré <[hidden email]>, wrote:
Hi

do you use the default Camel graceful shutdown strategy or a custom one ?

Regards
JB

On 02/06/2018 22:17, Joery Vreijsen 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

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

jbonofre
So, it seems that you have inflight messages and shutdown strategy are
longer then the blueprint container timeout.

I would start to change the shutdown strategy to be a little bit more
aggressive.

Regards
JB

On 03/06/2018 17:31, Joery Vreijsen wrote:

> Hi!
>
> Thanks for the quick response, yes I used the DefaultShutdownStrategy of
> Apache Camel 2.21.1.
>
> —
>
> Joery
> On 3 Jun 2018, 17:24 +0200, Jean-Baptiste Onofré <[hidden email]>, wrote:
>> Hi
>>
>> do you use the default Camel graceful shutdown strategy or a custom one ?
>>
>> Regards
>> JB
>>
>> On 02/06/2018 22:17, Joery Vreijsen 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
>>
>> --
>> Jean-Baptiste Onofré
>> [hidden email]
>> http://blog.nanthrax.net
>> Talend - http://www.talend.com

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

joeryv

Hi,

Correct, when I change the time-out in the Camel DefaultShutdownStrategy to 30 seconds (staying within the blueprint container timeout) the exception went away.

I’m just curious of why this seems to be a problem now as, if i recall correctly, it worked before.

Before, i mean when i upgraded our application from Karaf 4.0.4 to 4.2.0, and Camel from 2.18.3 to 2.20.1.

Thanks for the input so far!



Joery

> On 3 Jun 2018, at 18:47, Jean-Baptiste Onofré <[hidden email]> wrote:
>
> So, it seems that you have inflight messages and shutdown strategy are
> longer then the blueprint container timeout.
>
> I would start to change the shutdown strategy to be a little bit more
> aggressive.
>
> Regards
> JB
>
>> On 03/06/2018 17:31, Joery Vreijsen wrote:
>> Hi!
>>
>> Thanks for the quick response, yes I used the DefaultShutdownStrategy of
>> Apache Camel 2.21.1.
>>
>> —
>>
>> Joery
>>> On 3 Jun 2018, 17:24 +0200, Jean-Baptiste Onofré <[hidden email]>, wrote:
>>> Hi
>>>
>>> do you use the default Camel graceful shutdown strategy or a custom one ?
>>>
>>> Regards
>>> JB
>>>
>>>> On 02/06/2018 22:17, Joery Vreijsen 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
>>>
>>> --
>>> Jean-Baptiste Onofré
>>> [hidden email]
>>> http://blog.nanthrax.net
>>> Talend - http://www.talend.com
>
> --
> Jean-Baptiste Onofré
> [hidden email]
> http://blog.nanthrax.net
> Talend - http://www.talend.com
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

jbonofre
Hi,

Let me check if we change the timeout on the Camel and Aries Blueprint
sides.

It could be related to your inflight messages too, if they don't reach
the onCompletion quickly.

Regards
JB

On 03/06/2018 19:39, Joery Vreijsen wrote:

>
> Hi,
>
> Correct, when I change the time-out in the Camel DefaultShutdownStrategy to 30 seconds (staying within the blueprint container timeout) the exception went away.
>
> I’m just curious of why this seems to be a problem now as, if i recall correctly, it worked before.
>
> Before, i mean when i upgraded our application from Karaf 4.0.4 to 4.2.0, and Camel from 2.18.3 to 2.20.1.
>
> Thanks for the input so far!
>
> —
>
> Joery
>
>> On 3 Jun 2018, at 18:47, Jean-Baptiste Onofré <[hidden email]> wrote:
>>
>> So, it seems that you have inflight messages and shutdown strategy are
>> longer then the blueprint container timeout.
>>
>> I would start to change the shutdown strategy to be a little bit more
>> aggressive.
>>
>> Regards
>> JB
>>
>>> On 03/06/2018 17:31, Joery Vreijsen wrote:
>>> Hi!
>>>
>>> Thanks for the quick response, yes I used the DefaultShutdownStrategy of
>>> Apache Camel 2.21.1.
>>>
>>> —
>>>
>>> Joery
>>>> On 3 Jun 2018, 17:24 +0200, Jean-Baptiste Onofré <[hidden email]>, wrote:
>>>> Hi
>>>>
>>>> do you use the default Camel graceful shutdown strategy or a custom one ?
>>>>
>>>> Regards
>>>> JB
>>>>
>>>>> On 02/06/2018 22:17, Joery Vreijsen 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
>>>>
>>>> --
>>>> Jean-Baptiste Onofré
>>>> [hidden email]
>>>> http://blog.nanthrax.net
>>>> Talend - http://www.talend.com
>>
>> --
>> Jean-Baptiste Onofré
>> [hidden email]
>> http://blog.nanthrax.net
>> Talend - http://www.talend.com

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com
Reply | Threaded
Open this post in threaded view
|

Re: Karaf 4.2.0: java.util.concurrent.TimeoutException: null

joeryv
Hi JB!

Did you find any time to look at it?



Joery

https://theguild.nl
On 4 Jun 2018, 06:15 +0200, Jean-Baptiste Onofré <[hidden email]>, wrote:
Hi,

Let me check if we change the timeout on the Camel and Aries Blueprint
sides.

It could be related to your inflight messages too, if they don't reach
the onCompletion quickly.

Regards
JB

On 03/06/2018 19:39, Joery Vreijsen wrote:

Hi,

Correct, when I change the time-out in the Camel DefaultShutdownStrategy to 30 seconds (staying within the blueprint container timeout) the exception went away.

I’m just curious of why this seems to be a problem now as, if i recall correctly, it worked before.

Before, i mean when i upgraded our application from Karaf 4.0.4 to 4.2.0, and Camel from 2.18.3 to 2.20.1.

Thanks for the input so far!



Joery

On 3 Jun 2018, at 18:47, Jean-Baptiste Onofré <[hidden email]> wrote:

So, it seems that you have inflight messages and shutdown strategy are
longer then the blueprint container timeout.

I would start to change the shutdown strategy to be a little bit more
aggressive.

Regards
JB

On 03/06/2018 17:31, Joery Vreijsen wrote:
Hi!

Thanks for the quick response, yes I used the DefaultShutdownStrategy of
Apache Camel 2.21.1.



Joery
On 3 Jun 2018, 17:24 +0200, Jean-Baptiste Onofré <[hidden email]>, wrote:
Hi

do you use the default Camel graceful shutdown strategy or a custom one ?

Regards
JB

On 02/06/2018 22:17, Joery Vreijsen 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

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com

--
Jean-Baptiste Onofré
[hidden email]
http://blog.nanthrax.net
Talend - http://www.talend.com