[ARIES-1991] Unpredictible InterruptedException when starting bundles

• Type: Bug
• Status: Open
• Priority: Critical
• Resolution: Unresolved
• Affects Version/s: blueprint-core-1.10.2
• Component/s: Blueprint
• Assignee: Unassigned
• Reporter: nizar.ben.mansour
• Created: 21/Jul/20 11:04
• Updated: 13/Feb/21 05:44

Description

Hello,

I'm facing an issue that happens sometimes when starting my bundles that occurs only after TimeoutException (i think it relates to this issue  https://issues.apache.org/jira/browse/ARIES-1990) .

 

Here is the full log:

 

 
Attempting to start CamelContext: MappingCustomerIdLDdnContextAttempting to start CamelContext: MappingCustomerIdLDdnContext2020-07-20T19:29:05,304 | INFO  | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Apache Camel 2.23.4 (CamelContext: MappingCustomerIdLDdnContext) is starting2020-07-20T19:29:05,304 | INFO  | Blueprint Event Dispatcher: 1 | ManagedManagementStrategy        | 120 - org.apache.camel.camel-core - 2.23.4 | JMX is enabled2020-07-20T19:30:05,304 | WARN  | FelixStartLevel  | BlueprintEventDispatcher         | 100 - org.apache.aries.blueprint.core - 1.10.2 | Listener timed out, will be ignoredjava.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:185) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper$15.call(ScheduledExecutorServiceWrapper.java:446) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.RWLock.runReadOperation(RWLock.java:33) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper.runUnlessShutdown(ScheduledExecutorServiceWrapper.java:443) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper.invokeAny(ScheduledExecutorServiceWrapper.java:180) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher.callListener(BlueprintEventDispatcher.java:188) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher.callListeners(BlueprintEventDispatcher.java:178) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher.blueprintEvent(BlueprintEventDispatcher.java:133) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(BlueprintContainerImpl.java:447) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintContainerImpl.run(BlueprintContainerImpl.java:298) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:311) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:280) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:276) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:266) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422) [100:org.apache.aries.blueprint.core:1.10.2] 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.startBundle(Felix.java:2174) [?:?] at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1373) [?:?] at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308) [?:?] at java.lang.Thread.run(Thread.java:748) [?:?]2020-07-20T19:30:08,049 | INFO  | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Apache Camel 2.23.4 (CamelContext: MappingCustomerIdLDdnContext) is shutting down2020-07-20T19:30:08,065 | INFO  | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Apache Camel 2.23.4 (CamelContext: MappingCustomerIdLDdnContext) uptime 1 minute2020-07-20T19:30:08,066 | INFO  | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Apache Camel 2.23.4 (CamelContext: MappingCustomerIdLDdnContext) is shutdown in 0.017 seconds2020-07-20T19:30:08,066 | WARN  | Blueprint Event Dispatcher: 1 | BlueprintCamelStateService       | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Changing Camel state for bundle 86 to Failure2020-07-20T19:30:08,066 | ERROR | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Error occurred during starting CamelContext: MappingCustomerIdLDdnContextorg.apache.camel.RuntimeCamelException: java.lang.RuntimeException: java.lang.InterruptedException at org.apache.camel.util.ObjectHelper.wrapRuntimeCamelException(ObjectHelper.java:1826) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.getTypeConverter(DefaultCamelContext.java:2569) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.getTypeConverterRegistry(DefaultCamelContext.java:2590) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.forceLazyInitialization(DefaultCamelContext.java:4097) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.doStartCamel(DefaultCamelContext.java:3376) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext$4.call(DefaultCamelContext.java:3247) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext$4.call(DefaultCamelContext.java:3243) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.doWithDefinedClassLoader(DefaultCamelContext.java:3266) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.doStart(DefaultCamelContext.java:3243) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.support.ServiceSupport.start(ServiceSupport.java:72) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.impl.DefaultCamelContext.start(DefaultCamelContext.java:3159) ~[120:org.apache.camel.camel-core:2.23.4] at org.apache.camel.blueprint.BlueprintCamelContext.start(BlueprintCamelContext.java:255) ~[118:org.apache.camel.camel-blueprint:2.23.4] at org.apache.camel.blueprint.BlueprintCamelContext.maybeStart(BlueprintCamelContext.java:297) ~[118:org.apache.camel.camel-blueprint:2.23.4] at org.apache.camel.blueprint.BlueprintCamelContext.blueprintEvent(BlueprintCamelContext.java:188) [118:org.apache.camel.camel-blueprint:2.23.4] at org.apache.aries.blueprint.container.BlueprintEventDispatcher$3.call(BlueprintEventDispatcher.java:190) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher$3.call(BlueprintEventDispatcher.java:188) [100:org.apache.aries.blueprint.core:1.10.2] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?] at java.lang.Thread.run(Thread.java:748) [?:?]Caused by: java.lang.RuntimeException: java.lang.InterruptedException at org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:369) ~[?:?] at org.apache.felix.framework.Felix.getService(Felix.java:3737) ~[?:?] at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:470) ~[?:?] at org.apache.camel.core.osgi.OsgiTypeConverter.addingService(OsgiTypeConverter.java:69) ~[?:?] at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) ~[?:?] at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) ~[?:?] at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?] at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) ~[?:?] at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318) ~[?:?] at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261) ~[?:?] at org.apache.camel.core.osgi.OsgiTypeConverter.doStart(OsgiTypeConverter.java:101) ~[?:?] at org.apache.camel.support.ServiceSupport.start(ServiceSupport.java:72) ~[?:?] at org.apache.camel.util.ServiceHelper.startService(ServiceHelper.java:75) ~[?:?] at org.apache.camel.impl.DefaultCamelContext.doAddService(DefaultCamelContext.java:1486) ~[?:?] at org.apache.camel.impl.DefaultCamelContext.addService(DefaultCamelContext.java:1446) ~[?:?] at org.apache.camel.impl.DefaultCamelContext.getTypeConverter(DefaultCamelContext.java:2567) ~[?:?] ... 24 moreCaused by: java.lang.InterruptedException at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1302) ~[?:?] at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231) ~[?:?] at org.apache.felix.framework.ServiceRegistry.getService(ServiceRegistry.java:365) ~[?:?] at org.apache.felix.framework.Felix.getService(Felix.java:3737) ~[?:?] at org.apache.felix.framework.BundleContextImpl.getService(BundleContextImpl.java:470) ~[?:?] at org.apache.camel.core.osgi.OsgiTypeConverter.addingService(OsgiTypeConverter.java:69) ~[?:?] at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941) ~[?:?] at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870) ~[?:?] at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256) ~[?:?] at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183) ~[?:?] at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318) ~[?:?] at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261) ~[?:?] at org.apache.camel.core.osgi.OsgiTypeConverter.doStart(OsgiTypeConverter.java:101) ~[?:?] at org.apache.camel.support.ServiceSupport.start(ServiceSupport.java:72) ~[?:?] at org.apache.camel.util.ServiceHelper.startService(ServiceHelper.java:75) ~[?:?] at org.apache.camel.impl.DefaultCamelContext.doAddService(DefaultCamelContext.java:1486) ~[?:?] at org.apache.camel.impl.DefaultCamelContext.addService(DefaultCamelContext.java:1446) ~[?:?] at org.apache.camel.impl.DefaultCamelContext.getTypeConverter(DefaultCamelContext.java:2567) ~[?:?] ... 24 more2020-07-20T19:30:08,070 | INFO  | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Attempting to start CamelContext: mappingCustomerIdLdnContext2020-07-20T19:30:08,071 | INFO  | Blueprint Event Dispatcher: 1 | BlueprintCamelContext            | 118 - org.apache.camel.camel-blueprint - 2.23.4 | Apache Camel 2.23.4 (CamelContext: mappingCustomerIdLdnContext) is starting2020-07-20T19:30:08,071 | INFO  | Blueprint Event Dispatcher: 1 | ManagedManagementStrategy        | 120 - org.apache.camel.camel-core - 2.23.4 | JMX is enabled2020-07-20T19:30:29,223 | INFO  | activator-1-thread-1 | ServiceComponentRuntimeMBeanImpl | 181 - org.apache.karaf.scr.management - 4.2.6 | Activating the Apache Karaf ServiceComponentRuntime MBean2020-07-20T19:31:05,306 | WARN  | FelixStartLevel  | BlueprintEventDispatcher         | 100 - org.apache.aries.blueprint.core - 1.10.2 | Listener timed out, will be ignoredjava.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:185) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper$15.call(ScheduledExecutorServiceWrapper.java:446) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.RWLock.runReadOperation(RWLock.java:33) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper.runUnlessShutdown(ScheduledExecutorServiceWrapper.java:443) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.utils.threading.ScheduledExecutorServiceWrapper.invokeAny(ScheduledExecutorServiceWrapper.java:180) ~[100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher.callListener(BlueprintEventDispatcher.java:188) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher.callListeners(BlueprintEventDispatcher.java:178) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintEventDispatcher.blueprintEvent(BlueprintEventDispatcher.java:133) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintContainerImpl.doRun(BlueprintContainerImpl.java:447) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintContainerImpl.run(BlueprintContainerImpl.java:298) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:311) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:280) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.createContainer(BlueprintExtender.java:276) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:266) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463) [100:org.apache.aries.blueprint.core:1.10.2] at org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422) [100:org.apache.aries.blueprint.core:1.10.2] 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.startBundle(Felix.java:2174) [?:?] at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1373) [?:?] at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308) [?:?] at java.lang.Thread.run(Thread.java:748) [?:?]2020-07-20T19:31:11,612 | WARN  | Blueprint Event Dispatcher: 1 | DefaultTypeConverter             | 120 - org.apache.camel.camel-core - 2.23.4 | Overriding type converter from: 

 

Issue Links

• is related to: ARIES-1990 Hardcoded starting bundle timeout to 60 second