Hello all,
We have a few very busy routes that are throwing FileNotFoundExceptions when
processing files (full stacktrace below). Searching for those filenames in the
log it is very clear that those files have already been processed in the past
minute and thus are not there.
After removing the 1 minute schedule and adding a 1 minute delay the problems
have disappeared.
After testing it looks like a cron scheduler can only start 1 thread/worker per
route and a next scheduler ping will wait for the previous one to be finished.
Even if we manually trigger the route by its triggerId. This was tested by
holding a thread in a debugger for a few minutes, no new threads passed the
breakpoint until we let the first thread go. Still we are seeing what we are
seeing but I cannot create the volume of messages and routes in a test/develop
environment.
During low volume processing we can see multiple workers busy, but always in a
different minute then the other. So 1 thread/worker is busy per minute but the
worker name can differ.
During high volume processing at some point multiple workers will be
processing, the same route, in the same second. Also there have been moments we
can find 5 camellock files at the same time, in the same directory. There is
only 1 route per directory so there should not be more than 1 camellock, I
think.
Example from log (all the same routeId):
2016-03-14 23:35:38,783 [DefaultQuartzScheduler-esbContext-1_Worker-1]
2016-03-14 23:35:40,385 [DefaultQuartzScheduler-esbContext-1_Worker-7]
2016-03-14 23:35:40,620 [DefaultQuartzScheduler-esbContext-1_Worker-6]
2016-03-14 23:35:40,843 [DefaultQuartzScheduler-esbContext-1_Worker-8]
2016-03-14 23:35:41,262 [DefaultQuartzScheduler-esbContext-1_Worker-1]
2016-03-14 23:35:41,529 [DefaultQuartzScheduler-esbContext-1_Worker-2]
2016-03-14 23:35:43,200 [DefaultQuartzScheduler-esbContext-1_Worker-7]
2016-03-14 23:35:43,205 [DefaultQuartzScheduler-esbContext-1_Worker-6]
2016-03-14 23:35:44,470 [DefaultQuartzScheduler-esbContext-1_Worker-8]
2016-03-14 23:35:44,665 [DefaultQuartzScheduler-esbContext-1_Worker-1]
2016-03-14 23:35:45,503 [DefaultQuartzScheduler-esbContext-1_Worker-2]
2016-03-14 23:35:46,393 [DefaultQuartzScheduler-esbContext-1_Worker-7]
2016-03-14 23:35:47,051 [DefaultQuartzScheduler-esbContext-1_Worker-6]
The routes are very simple, from a mounted folder to a local directory with
nothing in between except for some onException handling for retrying and
sending to an error route (direct). Lowering maxMessagesPerPoll (250) did seem
to decrease the problem a bit but I am not convinced yet. This should be tested
with a number lower than 100.
from(file:///mnt/sl-nl/bij/outbox/?sortBy=ignoreCase:file:name&filter=#fileFilter&recursive=false&move=processed&moveFailed=failed&scheduler.cron=0+/1+0-23+?+*+1,2,3,4,5,6,7&scheduler=quartz2&scheduler.triggerId=nl_bij-export-to-archive-276)
to(file:///data/work/sl/work-archive/work/276/)
Is there anything we can change to make sure we have only one worker processing
at a time, per route? We seem to have 10 workers total that are divided amongst
the routes with schedulers. We have 250 routes total with a schedule. Most
schedules are every minute. Also there are 250 routes with delay=5s, but they
do not use those workers.
org.quartz.threadPool.threadCount is now at 1. We might need to increase this
number as we have 250 routes with a 1 minute schedule. But the issue we have is
quite the opposite of what to expect if quartz cannot trigger all jobs it
should trigger.
-----------------------------------------
version.camel 2.16.2
file:quartz.properties
org.quartz.scheduler.instanceName = QuartzScheduler
org.quartz.scheduler.threadsInheritContextClassLoaderOfInitializer = true
org.quartz.scheduler.skipUpdateCheck = true
org.quartz.scheduler.jmx.export = true
org.quartz.threadPool.class = org.quartz.simpl.SimpleThreadPool
org.quartz.threadPool.threadCount = 1
org.quartz.jobStore.class = org.quartz.simpl.RAMJobStore
server.info
Tomcat Version Apache Tomcat/8.0.26
JVM Version 1.8.0_60-b27
JVM Vendor Oracle Corporation
OS Name Linux
OS Version 3.8.13-98.2.2.el6uek.x86_64
OS Architecture amd64
2016-03-14 22:29:02,485 [DefaultQuartzScheduler-esbContext-1_Worker-10] errors
- WARN - Error stacktrace:
org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
store file: /data/work/sl/work-archive/work/276/DD_SOS2016031422110816.xml
at
org.apache.camel.component.file.FileOperations.storeFile(FileOperations.java:292)
at
org.apache.camel.component.file.GenericFileProducer.writeFile(GenericFileProducer.java:277)
at
org.apache.camel.component.file.GenericFileProducer.processExchange(GenericFileProducer.java:165)
at
org.apache.camel.component.file.GenericFileProducer.process(GenericFileProducer.java:79)
at
org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
at
org.apache.camel.processor.SendProcessor.process(SendProcessor.java:141)
at
org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77)
at
org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:460)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:190)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:121)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:83)
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:190)
at
org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:442)
at
org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:214)
at
org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:178)
at
org.apache.camel.impl.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:174)
at
org.apache.camel.impl.ScheduledPollConsumer.run(ScheduledPollConsumer.java:101)
at
org.apache.camel.pollconsumer.quartz2.QuartzScheduledPollConsumerJob.execute(QuartzScheduledPollConsumerJob.java:59)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
Caused by: org.apache.camel.InvalidPayloadException: No body available of type:
java.io.InputStream but has value:
GenericFile[/mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml] of type:
org.apache.camel.component.file.GenericFile on: DD_SOS2016031422110816.xml.
Caused by: Error during type conversion from type: java.lang.String to the
required type: byte[] with value [Body is file based:
GenericFile[/mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml]] due
java.io.FileNotFoundException: /mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml
(No such file or directory).
Exchange[ID-slesb101-60348-1457682250340-0-642502][DD_SOS2016031422110816.xml].
Caused by: [org.apache.camel.TypeConversionException - Error during type
conversion from type: java.lang.String to the required type: byte[] with value
[Body is file based:
GenericFile[/mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml]] due
java.io.FileNotFoundException: /mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml
(No such file or directory)]
at
org.apache.camel.impl.MessageSupport.getMandatoryBody(MessageSupport.java:101)
at
org.apache.camel.component.file.FileOperations.storeFile(FileOperations.java:273)
... 19 more
Caused by: org.apache.camel.TypeConversionException: Error during type
conversion from type: java.lang.String to the required type: byte[] with value
[Body is file based:
GenericFile[/mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml]] due
java.io.FileNotFoundException: /mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml
(No such file or directory)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.createTypeConversionException(BaseTypeConverterRegistry.java:610)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.mandatoryConvertTo(BaseTypeConverterRegistry.java:177)
at
org.apache.camel.component.file.FileBinding.loadContent(FileBinding.java:57)
at
org.apache.camel.component.file.GenericFileConverter.genericFileToInputStream(GenericFileConverter.java:123)
at sun.reflect.GeneratedMethodAccessor559.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.apache.camel.util.ObjectHelper.invokeMethod(ObjectHelper.java:1243)
at
org.apache.camel.impl.converter.StaticMethodTypeConverter.convertTo(StaticMethodTypeConverter.java:59)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.doConvertTo(BaseTypeConverterRegistry.java:293)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.mandatoryConvertTo(BaseTypeConverterRegistry.java:168)
at
org.apache.camel.impl.MessageSupport.getMandatoryBody(MessageSupport.java:99)
... 20 more
Caused by: org.apache.camel.RuntimeCamelException:
java.io.FileNotFoundException: /mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml
(No such file or directory)
at
org.apache.camel.util.ObjectHelper.wrapRuntimeCamelException(ObjectHelper.java:1642)
at
org.apache.camel.util.ObjectHelper.invokeMethod(ObjectHelper.java:1247)
at
org.apache.camel.impl.converter.StaticMethodTypeConverter.convertTo(StaticMethodTypeConverter.java:59)
at
org.apache.camel.component.file.GenericFileConverter.convertTo(GenericFileConverter.java:97)
at sun.reflect.GeneratedMethodAccessor555.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.apache.camel.util.ObjectHelper.invokeMethod(ObjectHelper.java:1243)
at
org.apache.camel.impl.converter.StaticMethodFallbackTypeConverter.convertTo(StaticMethodFallbackTypeConverter.java:62)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.doConvertTo(BaseTypeConverterRegistry.java:333)
at
org.apache.camel.impl.converter.BaseTypeConverterRegistry.mandatoryConvertTo(BaseTypeConverterRegistry.java:168)
... 30 more
Caused by: java.io.FileNotFoundException:
/mnt/sl-nl/bij/outbox/DD_SOS2016031422110816.xml (No such file or directory)
at java.io.FileInputStream.open0(Native Method)
at java.io.FileInputStream.open(FileInputStream.java:195)
at java.io.FileInputStream.<init>(FileInputStream.java:138)
at
org.apache.camel.converter.IOConverter.toInputStream(IOConverter.java:78)
at
org.apache.camel.converter.IOConverter.toByteArray(IOConverter.java:266)
at sun.reflect.GeneratedMethodAccessor604.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.apache.camel.util.ObjectHelper.invokeMethod(ObjectHelper.java:1243)
... 39 more
