The problem does appear to be parallel processing in the splitter. If I turn
that off, the route works perfectly every time. I stripped out any reference
to activemq and jms routing in my blueprint.xml files.I also striped out the
aggregator. As for the JPA services that I'm using to handle the actual
database persistence, these are just simple entitymanager.persist(object)
calls against a postgresql database. There is no state maintained in these
services with the exception of the EntityManager, which is right out of the
Aries JPA documentation:
I tried setting trace=true in the route and exception stacktracing in my
error handler, and am not getting any errors when the route hangs with
parallel processing turned on.
The only error output I get is when I stop the bundle in my Karaf console.
Usually, the route hangs with one or two messages from the splitter to
complete.
Turning off parallel processing is not an option, as I expect to be handling
large record files to import and I don't want it to take all day.
Where can I turn to try and fix this?
Here is the log output from stoping the bundle:
2013-05-19 15:02:58,956 | INFO | Thread-390 | BlueprintExtender
| nt.container.BlueprintExtender$3 282 | 7 -
org.apache.aries.blueprint.core - 1.1.0 | Destroying BlueprintContainer for
bundle com.dsi.edispense.import
2013-05-19 15:02:58,961 | INFO | Thread-390 | BlueprintCamelContext
| e.camel.impl.DefaultCamelContext 1624 | 149 - org.apache.camel.camel-core
- 2.11.0 | Apache Camel 2.11.0 (CamelContext: 332-camel-99) is shutting down
2013-05-19 15:02:58,962 | INFO | Thread-390 | DefaultShutdownStrategy
| mel.impl.DefaultShutdownStrategy 165 | 149 - org.apache.camel.camel-core
- 2.11.0 | Starting to graceful shutdown 1 routes (timeout 300 seconds)
2013-05-19 15:02:58,967 | INFO | 1 - ShutdownTask | DefaultShutdownStrategy
| ultShutdownStrategy$ShutdownTask 536 | 149 - org.apache.camel.camel-core
- 2.11.0 | Waiting as there are still 1 inflight and pending exchanges to
complete, timeout in 300 seconds.
2013-05-19 15:02:59,967 | INFO | 1 - ShutdownTask | DefaultShutdownStrategy
| ultShutdownStrategy$ShutdownTask 536 | 149 - org.apache.camel.camel-core
- 2.11.0 | Waiting as there are still 1 inflight and pending exchanges to
complete, timeout in 299 seconds.
2013-05-19 15:03:00,968 | INFO | 1 - ShutdownTask | DefaultShutdownStrategy
| ultShutdownStrategy$ShutdownTask 536 | 149 - org.apache.camel.camel-core
- 2.11.0 | Waiting as there are still 1 inflight and pending exchanges to
complete, timeout in 298 seconds.
2013-05-19 15:03:01,968 | INFO | 1 - ShutdownTask | DefaultShutdownStrategy
| ultShutdownStrategy$ShutdownTask 536 | 149 - org.apache.camel.camel-core
- 2.11.0 | Waiting as there are still 1 inflight and pending exchanges to
complete, timeout in 297 seconds.
2013-05-19 15:03:02,187 | WARN | Thread-390 | BlueprintCamelContext
| e.camel.impl.DefaultCamelContext 1632 | 149 - org.apache.camel.camel-core
- 2.11.0 | Error occurred while shutting down routes. This exception will be
ignored.
java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1038)[:1.7.0_09-icedtea]
at
java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1326)[:1.7.0_09-icedtea]
at
java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:257)[:1.7.0_09-icedtea]
at
java.util.concurrent.FutureTask.get(FutureTask.java:119)[:1.7.0_09-icedtea]
at
org.apache.camel.impl.DefaultShutdownStrategy.doShutdown(DefaultShutdownStrategy.java:174)
at
org.apache.camel.impl.DefaultShutdownStrategy.shutdownForced(DefaultShutdownStrategy.java:122)
at
org.apache.camel.impl.DefaultCamelContext.doStop(DefaultCamelContext.java:1630)
at org.apache.camel.support.ServiceSupport.stop(ServiceSupport.java:92)
at
org.apache.camel.blueprint.BlueprintCamelContext.destroy(BlueprintCamelContext.java:109)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
Method)[:1.7.0_09-icedtea]
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)[:1.7.0_09-icedtea]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.7.0_09-icedtea]
at java.lang.reflect.Method.invoke(Method.java:601)[:1.7.0_09-icedtea]
at
org.apache.aries.blueprint.utils.ReflectionUtils.invoke(ReflectionUtils.java:297)
at
org.apache.aries.blueprint.container.BeanRecipe.invoke(BeanRecipe.java:958)
at
org.apache.aries.blueprint.container.BeanRecipe.destroy(BeanRecipe.java:863)
at
org.apache.aries.blueprint.container.BlueprintRepository.destroy(BlueprintRepository.java:320)
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.destroyComponents(BlueprintContainerImpl.java:709)
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.tidyupComponents(BlueprintContainerImpl.java:908)
at
org.apache.aries.blueprint.container.BlueprintContainerImpl.destroy(BlueprintContainerImpl.java:857)
at
org.apache.aries.blueprint.container.BlueprintExtender$3.run(BlueprintExtender.java:284)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)[:1.7.0_09-icedtea]
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)[:1.7.0_09-icedtea]
at
java.util.concurrent.FutureTask.run(FutureTask.java:166)[:1.7.0_09-icedtea]
at
org.apache.aries.blueprint.container.BlueprintExtender.destroyContainer(BlueprintExtender.java:305)
at
org.apache.aries.blueprint.container.BlueprintExtender.modifiedBundle(BlueprintExtender.java:206)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:500)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.customizerModified(BundleHookBundleTracker.java:433)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$AbstractTracked.track(BundleHookBundleTracker.java:725)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$Tracked.bundleChanged(BundleHookBundleTracker.java:463)
at
org.apache.aries.util.tracker.hook.BundleHookBundleTracker$BundleEventHook.event(BundleHookBundleTracker.java:422)
at
org.apache.felix.framework.util.SecureAction.invokeBundleEventHook(SecureAction.java:1103)
at
org.apache.felix.framework.util.EventDispatcher.createWhitelistFromHooks(EventDispatcher.java:695)
at
org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:483)
at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4244)
at org.apache.felix.framework.Felix.stopBundle(Felix.java:2351)
at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:980)
at org.apache.felix.framework.BundleImpl.stop(BundleImpl.java:967)
at org.apache.karaf.shell.osgi.StopBundle.doExecute(StopBundle.java:37)
at
org.apache.karaf.shell.osgi.BundlesCommand.doExecute(BundlesCommand.java:37)
at
org.apache.karaf.shell.console.OsgiCommandSupport.execute(OsgiCommandSupport.java:38)
at
org.apache.felix.gogo.commands.basic.AbstractCommand.execute(AbstractCommand.java:35)
at
org.apache.felix.gogo.runtime.CommandProxy.execute(CommandProxy.java:78)
at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:474)
at
org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:400)
at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:183)
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:120)
at
org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:89)
at org.apache.karaf.shell.console.jline.Console.run(Console.java:174)
at java.lang.Thread.run(Thread.java:722)[:1.7.0_09-icedtea]
at
org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4.doRun(ShellFactoryImpl.java:144)[28:org.apache.karaf.shell.ssh:2.3.1]
at
org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4$1.run(ShellFactoryImpl.java:135)
at java.security.AccessController.doPrivileged(Native
Method)[:1.7.0_09-icedtea]
at javax.security.auth.Subject.doAs(Subject.java:356)[:1.7.0_09-icedtea]
at
org.apache.karaf.shell.ssh.ShellFactoryImpl$ShellImpl$4.run(ShellFactoryImpl.java:133)[28:org.apache.karaf.shell.ssh:2.3.1]
2013-05-19 15:03:02,211 | ERROR | amel-99_Worker-1 | QuartzEndpoint
| .component.quartz.QuartzEndpoint 121 | 264 -
org.apache.camel.camel-quartz - 2.11.0 | Error processing exchange.
Exchange[Message: [[12838452, Rolando, , Ambrosia, 2120754, 602-54-8586,
1967-01-02, M, 211 Pearidge Road, , Canton, IN, 30114, 6784938507, ,
English, , ABC Co., , , , , , , 2013-01-24, 721.3, , WC000266, Sedgwick CMS
Work Comp, PO Box 1288, , Bentonville, AR, 72712, , ], [12821493, TERRY, ,
BOYCE, 404, 223-76-8976, 1956-02-22, M, 94 BOXELDER CT, , DALLAS, GA, 30132,
6785748005, , English, , , , , , , , , 2010-07-18, 726.2, 62295698,
WC002337, US DEPT OF LABOR, PO BOX 8300, , LONDON, KY, 40742, 8505581818, ],
[12829661, Terrell, , Hall, , 259-477-908, 1984-05-26, M, 205 Peppertree, ,
Griffin, GA, 30224, 6785443385, , English, , , , , , , , , 2011-12-11,
724.2, A00514, WC002368, NOVAPRO RISK SOLUTIONS, 4508 OAKFAIR BLVD SUITE
270, , TAMPA, FL, 33610, 8136216949, ], [12861297, Terrell, , Ball, ,
259-47-7908, 1984-05-26, M, 205 Peppertree, , Griffin, GA, 30224,
6785443385, , English, , , , , , , , , 2011-12-11, 724.2, A00514, WC002368,
NOVAPRO RISK SOLUTIONS, 4508 OAKFAIR BLVD SUITE 270, , TAMPA, FL, 33610...
[Body clipped after 1000 chars, total length is 5259]]. Caused by:
[org.quartz.JobExecutionException - java.lang.InterruptedException]
2013-05-19 15:03:02,211 | INFO | amel-99_Worker-1 | JobRunShell
| org.quartz.core.JobRunShell 228 | 263 -
org.apache.servicemix.bundles.quartz - 1.8.6.1 | Job
DEFAULT.quartz-endpoint67 threw a JobExecutionException:
org.quartz.JobExecutionException: java.lang.InterruptedException [See nested
exception: java.lang.InterruptedException]
at
org.apache.camel.component.quartz.QuartzEndpoint.onJobExecute(QuartzEndpoint.java:117)[264:org.apache.camel.camel-quartz:2.11.0]
at
org.apache.camel.component.quartz.CamelJob.execute(CamelJob.java:61)[264:org.apache.camel.camel-quartz:2.11.0]
at
org.quartz.core.JobRunShell.run(JobRunShell.java:223)[263:org.apache.servicemix.bundles.quartz:1.8.6.1]
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:549)[263:org.apache.servicemix.bundles.quartz:1.8.6.1]
Caused by: java.lang.InterruptedException
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)[:1.7.0_09-icedtea]
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2095)[:1.7.0_09-icedtea]
at
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)[:1.7.0_09-icedtea]
at
java.util.concurrent.ExecutorCompletionService.poll(ExecutorCompletionService.java:202)[:1.7.0_09-icedtea]
at
org.apache.camel.processor.MulticastProcessor$AggregateOnTheFlyTask.aggregateOnTheFly(MulticastProcessor.java:425)[149:org.apache.camel.camel-core:2.11.0]
at
org.apache.camel.processor.MulticastProcessor$AggregateOnTheFlyTask.run(MulticastProcessor.java:380)[149:org.apache.camel.camel-core:2.11.0]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)[:1.7.0_09-icedtea]
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)[:1.7.0_09-icedtea]
at
java.util.concurrent.FutureTask.run(FutureTask.java:166)[:1.7.0_09-icedtea]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)[:1.7.0_09-icedtea]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)[:1.7.0_09-icedtea]
at java.lang.Thread.run(Thread.java:722)[:1.7.0_09-icedtea]
2013-05-19 15:03:02,212 | INFO | Thread-390 | QuartzComponent
| component.quartz.QuartzComponent 209 | 264 -
org.apache.camel.camel-quartz - 2.11.0 | There are no more jobs registered,
so shutting down Quartz scheduler: DefaultQuartzScheduler-332-camel-99
2013-05-19 15:03:02,212 | INFO | Thread-390 | QuartzScheduler
| org.quartz.core.QuartzScheduler 635 | 263 -
org.apache.servicemix.bundles.quartz - 1.8.6.1 | Scheduler
DefaultQuartzScheduler-332-camel-99_$_NON_CLUSTERED shutting down.
2013-05-19 15:03:02,212 | INFO | Thread-390 | QuartzScheduler
| org.quartz.core.QuartzScheduler 556 | 263 -
org.apache.servicemix.bundles.quartz - 1.8.6.1 | Scheduler
DefaultQuartzScheduler-332-camel-99_$_NON_CLUSTERED paused.
2013-05-19 15:03:02,215 | INFO | Thread-390 | QuartzScheduler
| org.quartz.core.QuartzScheduler 707 | 263 -
org.apache.servicemix.bundles.quartz - 1.8.6.1 | Scheduler
DefaultQuartzScheduler-332-camel-99_$_NON_CLUSTERED shutdown complete.
2013-05-19 15:03:02,216 | WARN | 1 - ShutdownTask | DefaultShutdownStrategy
| ultShutdownStrategy$ShutdownTask 544 | 149 - org.apache.camel.camel-core
- 2.11.0 | Interrupted while waiting during graceful shutdown, will force
shutdown now.
2013-05-19 15:03:02,218 | INFO | 1 - ShutdownTask | DefaultShutdownStrategy
| ultShutdownStrategy$ShutdownTask 572 | 149 - org.apache.camel.camel-core
- 2.11.0 | Route: patient_import shutdown complete, was consuming from:
Endpoint[quartz://myTimerName?trigger.repeatCount=0&trigger.repeatInterval=5000]
2013-05-19 15:03:02,219 | INFO | Thread-390 | BlueprintCamelContext
| e.camel.impl.DefaultCamelContext 1695 | 149 - org.apache.camel.camel-core
- 2.11.0 | Uptime 32.426 seconds
2013-05-19 15:03:02,219 | INFO | Thread-390 | BlueprintCamelContext
| e.camel.impl.DefaultCamelContext 1696 | 149 - org.apache.camel.camel-core
- 2.11.0 | Apache Camel 2.11.0 (CamelContext: 332-camel-99) is shutdown in
3.258 seconds
--
View this message in context:
http://camel.465427.n5.nabble.com/Asynchronous-routing-with-jms-hangs-in-midstream-tp5732805p5732823.html
Sent from the Camel - Users mailing list archive at Nabble.com.
