You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@camel.apache.org by Santiago Acosta <sa...@intermodaltelematics.com> on 2021/12/16 20:20:03 UTC
camel-quartz is misfiring on startup
Camel 3.13 (but I also tried 3.6 and results are worse)
I have an issue where a quartz route is misfiring at the beginning of the
startup. I ran some standalone Quartz scheduler with a simple job and
trigger and it works as expected, even with a small interval (<200ms).
In the case of Camel, the interval is not being respected in the first few
exchanges.
Notice at the end of the log how the first QUARTZ log entries are piled
together (interval 1200). If I shorten the interval I can pile them up even
more (3 entries in 100ms with interval 200ms)
...:46,750 INFO [main ] o.a.c.t.j.CamelTestSupport -
********************************************************************************
...:46,753 INFO [main ] o.a.c.t.j.CamelTestSupport - Testing: a()
(BlahTest)
...:46,755 INFO [main ] o.a.c.t.j.CamelTestSupport -
********************************************************************************
...:46,915 INFO [main ] .s.o.s.BlahTest$bootstrapper$1 - Run event
handler 1/1 for BEFORE_CONF
...:47,252 INFO [main ] o.a.c.i.e.AbstractCamelContext - MDC logging is
enabled on CamelContext: camel-1
...:47,253 INFO [main ] o.a.c.c.quartz.QuartzComponent - Create and
initializing scheduler.
...:47,254 INFO [main ] o.a.c.c.quartz.QuartzComponent - Setting
org.quartz.scheduler.jmx.export=true to ensure QuartzScheduler(s) will be
enlisted in JMX.
...:47,314 INFO [main ] o.q.impl.StdSchedulerFactory - Using default
implementation for ThreadExecutor
...:47,318 INFO [main ] o.q.simpl.SimpleThreadPool - Job execution
threads will use class loader of thread: main
...:47,332 INFO [main ] o.q.core.SchedulerSignalerImpl - Initialized
Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
...:47,333 INFO [main ] o.quartz.core.QuartzScheduler - Quartz
Scheduler v.2.3.2 created.
...:47,334 INFO [main ] org.quartz.simpl.RAMJobStore - RAMJobStore
initialized.
...:47,514 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler-camel-1' with
instanceId 'NON_CLUSTERED'
Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
NOT STARTED.
Currently in standby mode.
Number of jobs executed: 0
Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads.
Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support
persistence. and is not clustered.
...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
scheduler 'DefaultQuartzScheduler-camel-1' initialized from an externally
provided properties instance.
...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
scheduler version: 2.3.2
...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
19:54:47 WET 2021
...:47,977 INFO [main ] o.a.c.i.e.AbstractCamelContext - Routes startup
summary (total:2 started:2)
...:47,977 INFO [main ] o.a.c.i.e.AbstractCamelContext - Started
quartz-daemon (quartz://resolver)
...:47,977 INFO [main ] o.a.c.i.e.AbstractCamelContext - Started
route1 (seda://out)
...:47,977 INFO [main ] o.a.c.i.e.AbstractCamelContext - Apache Camel
3.13.0 (camel-1) started in 1s26ms (build:96ms init:205ms start:725ms)
...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
scheduler.
...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
...:47,993 INFO [main ] o.a.c.c.mock.MockEndpoint - Asserting:
mock://end is satisfied
...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
...:49,923 INFO [Worker-3] quartz-daemon - QUARTZ
...:51,122 INFO [Worker-4] quartz-daemon - QUARTZ
...:52,321 INFO [Worker-5] quartz-daemon - QUARTZ
...:53,523 INFO [Worker-6] quartz-daemon - QUARTZ
...:54,526 INFO [main ] o.a.c.c.mock.MockEndpoint - Re-asserting:
mock://end is satisfied after 1000 millis
The route I am using is incredibly simple
from("quartz:resolver?trigger.repeatInterval=1200&stateful=true&triggerStartDelay=0")
.id("quartz-daemon")
.log("QUARTZ")
.process(processorName) // trivial, creates arrays with 2-3
random Int
.marshal()
.json(JsonLibrary.Jackson)
.to("mock:end")
Am I missing some specific Camel-Quartz configuration that would cause
these misfires?
I would like the scheduler to respect the interval, is this a Quartz issue?
Am I missing some specific misfire configuration that deals with these
cases?
Re: camel-quartz is misfiring on startup
Posted by Santiago Acosta <sa...@intermodaltelematics.com>.
Thanks Claus! I had completely overlooked such simple ootb solutions!
However, our current solution is working quite well so we will not be
revisiting for the time being.
Thanks again. There is so much more to learn and test
On Tue, Jan 11, 2022 at 11:59 AM Claus Ibsen <cl...@gmail.com> wrote:
> Hi
>
> For quartz then one of its only benefits is its cron support.
> If you just want to trigger every X interval, then use camel-timer or
> camel-scheduler (latter more advanced).
>
> And for cron, there is in fact also camel-spring where they have cron
> support.
>
> On Tue, Jan 11, 2022 at 11:50 AM Santiago Acosta
> <sa...@intermodaltelematics.com> wrote:
> >
> > Thanks for the info Karen, but I am sad to say we had to move on to use
> > something else (I think VertX which also has integrations with Camel).
> I'll
> > keep this close to the chest when the opportunity to use Camel+Quartz
> comes
> > around again.
> >
> > I'll keep an eye on https://issues.apache.org/jira/browse/CAMEL-17446
> >
> > On Thu, Jan 6, 2022 at 4:25 PM Karen Lease <ka...@gmail.com>
> wrote:
> >
> > > Hi Santiago,
> > >
> > > Sorry for the late reply, but it seems no one else picked up on this
> yet.
> > > I think the behavior you see is related to the time between the
> creation
> > > of the job trigger in Quartz and when Camel finishes initializing and
> > > the Quartz scheduler is actually started.
> > >
> > > The initial fire time of the trigger for your job is set to the time
> > > when the trigger is created, not when the Quartz scheduler is actually
> > > started.
> > > Based on your logs and the Camel Quartz code, the trigger is created
> > > between the following 2 log messages, so between 19:54:47,514 and
> 47,545.
> > >
> > > > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > > > scheduler version: 2.3.2
> > > > ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> > > > Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> > > > jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec
> 16
> > > > 19:54:47 WET 2021
> > >
> > > Unfortunately the last message does not show the milliseconds in the
> > > start date, but we can see it is sometime in the second 19:54:47.
> > >
> > > It takes another 435 ms for Camel to finish its work and actually start
> > > the Quartz scheduler at 19:54:47,980:
> > > > ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent -
> Starting
> > > > scheduler.
> > > > ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler -
> Scheduler
> > > > DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
> > >
> > > Quartz fires the first event as soon as possible since the start time
> > > has already passed:
> > > > ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
> > >
> > > Adding 1200 ms to the possible start time range, the second one should
> > > have fired between 19:54:48,714 and 48,745 and it is fired at 48,722.
> > > > ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
> > >
> > >
> > > Set the logging level to DEBUG on
> > > org.apache.camel.component.quartz.QuartzEndpoint to see more details
> > > about the trigger creation but the behavior seems consistent.
> > >
> > > Unfortunately, if I correctly understand the code, setting
> > > triggerStartDelay to a postive number to account for the delay in
> > > starting the scheduler does not appear to work, since it sets the start
> > > time of the trigger only if it is *less* than 0 which seems
> > > counter-intuitive.
> > >
> > > In QuartzEndpoint.createTrigger():
> > > if (getComponent().getScheduler().isStarted() || triggerStartDelay <
> 0) {
> > > triggerBuilder.startAt(new Date(System.currentTimeMillis() +
> > > triggerStartDelay));
> > > }
> > >
> > > I hope this helps or at least explains the behavior.
> > > I created https://issues.apache.org/jira/browse/CAMEL-17446 related to
> > > the points I mentioned.
> > >
> > >
> > >
> > > On 16/12/2021 21:20, Santiago Acosta wrote:
> > > > Camel 3.13 (but I also tried 3.6 and results are worse)
> > > >
> > > > I have an issue where a quartz route is misfiring at the beginning
> of the
> > > > startup. I ran some standalone Quartz scheduler with a simple job and
> > > > trigger and it works as expected, even with a small interval
> (<200ms).
> > > >
> > > > In the case of Camel, the interval is not being respected in the
> first
> > > few
> > > > exchanges.
> > > >
> > > > Notice at the end of the log how the first QUARTZ log entries are
> piled
> > > > together (interval 1200). If I shorten the interval I can pile them
> up
> > > even
> > > > more (3 entries in 100ms with interval 200ms)
> > > >
> > >
> > > > ...:47,318 INFO [main ] o.q.simpl.SimpleThreadPool - Job
> > > execution
> > > > threads will use class loader of thread: main
> > > > ...:47,332 INFO [main ] o.q.core.SchedulerSignalerImpl -
> Initialized
> > > > Scheduler Signaller of type: class
> org.quartz.core.SchedulerSignalerImpl
> > > > ...:47,333 INFO [main ] o.quartz.core.QuartzScheduler - Quartz
> > > > Scheduler v.2.3.2 created.
> > > > ...:47,334 INFO [main ] org.quartz.simpl.RAMJobStore -
> RAMJobStore
> > > > initialized.
> > > > ...:47,514 INFO [main ] o.quartz.core.QuartzScheduler -
> Scheduler
> > > > meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler-camel-1'
> > > with
> > > > instanceId 'NON_CLUSTERED'
> > > > Scheduler class: 'org.quartz.core.QuartzScheduler' - running
> locally.
> > > > NOT STARTED.
> > > > Currently in standby mode.
> > > > Number of jobs executed: 0
> > > > Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10
> > > threads.
> > > > Using job-store 'org.quartz.simpl.RAMJobStore' - which does not
> > > support
> > > > persistence. and is not clustered.
> > > >
> > > > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > > > scheduler 'DefaultQuartzScheduler-camel-1' initialized from an
> externally
> > > > provided properties instance.
> > > > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > > > scheduler version: 2.3.2
> > > > ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> > > > Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> > > > jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> > > > 19:54:47 WET 2021
> > >
> > > > ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> > > > scheduler.
> > > > ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler -
> Scheduler
> > > > DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
> > > > ...:47,993 INFO [main ] o.a.c.c.mock.MockEndpoint -
> Asserting:
> > > > mock://end is satisfied
> > > > ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
> > > > ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
> > > > ...:49,923 INFO [Worker-3] quartz-daemon - QUARTZ
> > > > ...:51,122 INFO [Worker-4] quartz-daemon - QUARTZ
> > > > ...:52,321 INFO [Worker-5] quartz-daemon - QUARTZ
> > > > ...:53,523 INFO [Worker-6] quartz-daemon - QUARTZ
> > > > ...:54,526 INFO [main ] o.a.c.c.mock.MockEndpoint -
> > > Re-asserting:
> > > > mock://end is satisfied after 1000 millis
> > > >
> > > > The route I am using is incredibly simple
> > > >
> > > >
> > > >
> > >
> from("quartz:resolver?trigger.repeatInterval=1200&stateful=true&triggerStartDelay=0")
> > > > .id("quartz-daemon")
> > > > .log("QUARTZ")
> > > > .process(processorName) // trivial, creates arrays
> with
> > > 2-3
> > > > random Int
> > > > .marshal()
> > > > .json(JsonLibrary.Jackson)
> > > > .to("mock:end")
> > > >
> > > > Am I missing some specific Camel-Quartz configuration that would
> cause
> > > > these misfires?
> > > >
> > > > I would like the scheduler to respect the interval, is this a Quartz
> > > issue?
> > > >
> > > > Am I missing some specific misfire configuration that deals with
> these
> > > > cases?
> > > >
> > >
> >
> >
> > --
> > Best regards,
> > *Santiago Acosta Arreaza*
> >
> > Intermodal Telematics S.L.
> > Prisma building, 1st floor, Office 1.5
> > Fotógrafo José Norberto Rguez. Díaz st., 2
> > San Cristobal de La Laguna, SC de Tenerife
> > 38204, Spain
> >
> >
> > +34 922 31 56 05
> > www.intermodaltelematics.com
>
>
>
> --
> Claus Ibsen
> -----------------
> http://davsclaus.com @davsclaus
> Camel in Action 2: https://www.manning.com/ibsen2
>
--
Best regards,
*Santiago Acosta Arreaza*
Intermodal Telematics S.L.
Prisma building, 1st floor, Office 1.5
Fotógrafo José Norberto Rguez. Díaz st., 2
San Cristobal de La Laguna, SC de Tenerife
38204, Spain
+34 922 31 56 05
www.intermodaltelematics.com
Re: camel-quartz is misfiring on startup
Posted by Claus Ibsen <cl...@gmail.com>.
Hi
For quartz then one of its only benefits is its cron support.
If you just want to trigger every X interval, then use camel-timer or
camel-scheduler (latter more advanced).
And for cron, there is in fact also camel-spring where they have cron support.
On Tue, Jan 11, 2022 at 11:50 AM Santiago Acosta
<sa...@intermodaltelematics.com> wrote:
>
> Thanks for the info Karen, but I am sad to say we had to move on to use
> something else (I think VertX which also has integrations with Camel). I'll
> keep this close to the chest when the opportunity to use Camel+Quartz comes
> around again.
>
> I'll keep an eye on https://issues.apache.org/jira/browse/CAMEL-17446
>
> On Thu, Jan 6, 2022 at 4:25 PM Karen Lease <ka...@gmail.com> wrote:
>
> > Hi Santiago,
> >
> > Sorry for the late reply, but it seems no one else picked up on this yet.
> > I think the behavior you see is related to the time between the creation
> > of the job trigger in Quartz and when Camel finishes initializing and
> > the Quartz scheduler is actually started.
> >
> > The initial fire time of the trigger for your job is set to the time
> > when the trigger is created, not when the Quartz scheduler is actually
> > started.
> > Based on your logs and the Camel Quartz code, the trigger is created
> > between the following 2 log messages, so between 19:54:47,514 and 47,545.
> >
> > > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > > scheduler version: 2.3.2
> > > ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> > > Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> > > jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> > > 19:54:47 WET 2021
> >
> > Unfortunately the last message does not show the milliseconds in the
> > start date, but we can see it is sometime in the second 19:54:47.
> >
> > It takes another 435 ms for Camel to finish its work and actually start
> > the Quartz scheduler at 19:54:47,980:
> > > ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> > > scheduler.
> > > ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> > > DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
> >
> > Quartz fires the first event as soon as possible since the start time
> > has already passed:
> > > ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
> >
> > Adding 1200 ms to the possible start time range, the second one should
> > have fired between 19:54:48,714 and 48,745 and it is fired at 48,722.
> > > ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
> >
> >
> > Set the logging level to DEBUG on
> > org.apache.camel.component.quartz.QuartzEndpoint to see more details
> > about the trigger creation but the behavior seems consistent.
> >
> > Unfortunately, if I correctly understand the code, setting
> > triggerStartDelay to a postive number to account for the delay in
> > starting the scheduler does not appear to work, since it sets the start
> > time of the trigger only if it is *less* than 0 which seems
> > counter-intuitive.
> >
> > In QuartzEndpoint.createTrigger():
> > if (getComponent().getScheduler().isStarted() || triggerStartDelay < 0) {
> > triggerBuilder.startAt(new Date(System.currentTimeMillis() +
> > triggerStartDelay));
> > }
> >
> > I hope this helps or at least explains the behavior.
> > I created https://issues.apache.org/jira/browse/CAMEL-17446 related to
> > the points I mentioned.
> >
> >
> >
> > On 16/12/2021 21:20, Santiago Acosta wrote:
> > > Camel 3.13 (but I also tried 3.6 and results are worse)
> > >
> > > I have an issue where a quartz route is misfiring at the beginning of the
> > > startup. I ran some standalone Quartz scheduler with a simple job and
> > > trigger and it works as expected, even with a small interval (<200ms).
> > >
> > > In the case of Camel, the interval is not being respected in the first
> > few
> > > exchanges.
> > >
> > > Notice at the end of the log how the first QUARTZ log entries are piled
> > > together (interval 1200). If I shorten the interval I can pile them up
> > even
> > > more (3 entries in 100ms with interval 200ms)
> > >
> >
> > > ...:47,318 INFO [main ] o.q.simpl.SimpleThreadPool - Job
> > execution
> > > threads will use class loader of thread: main
> > > ...:47,332 INFO [main ] o.q.core.SchedulerSignalerImpl - Initialized
> > > Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
> > > ...:47,333 INFO [main ] o.quartz.core.QuartzScheduler - Quartz
> > > Scheduler v.2.3.2 created.
> > > ...:47,334 INFO [main ] org.quartz.simpl.RAMJobStore - RAMJobStore
> > > initialized.
> > > ...:47,514 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> > > meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler-camel-1'
> > with
> > > instanceId 'NON_CLUSTERED'
> > > Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
> > > NOT STARTED.
> > > Currently in standby mode.
> > > Number of jobs executed: 0
> > > Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10
> > threads.
> > > Using job-store 'org.quartz.simpl.RAMJobStore' - which does not
> > support
> > > persistence. and is not clustered.
> > >
> > > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > > scheduler 'DefaultQuartzScheduler-camel-1' initialized from an externally
> > > provided properties instance.
> > > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > > scheduler version: 2.3.2
> > > ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> > > Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> > > jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> > > 19:54:47 WET 2021
> >
> > > ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> > > scheduler.
> > > ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> > > DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
> > > ...:47,993 INFO [main ] o.a.c.c.mock.MockEndpoint - Asserting:
> > > mock://end is satisfied
> > > ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
> > > ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
> > > ...:49,923 INFO [Worker-3] quartz-daemon - QUARTZ
> > > ...:51,122 INFO [Worker-4] quartz-daemon - QUARTZ
> > > ...:52,321 INFO [Worker-5] quartz-daemon - QUARTZ
> > > ...:53,523 INFO [Worker-6] quartz-daemon - QUARTZ
> > > ...:54,526 INFO [main ] o.a.c.c.mock.MockEndpoint -
> > Re-asserting:
> > > mock://end is satisfied after 1000 millis
> > >
> > > The route I am using is incredibly simple
> > >
> > >
> > >
> > from("quartz:resolver?trigger.repeatInterval=1200&stateful=true&triggerStartDelay=0")
> > > .id("quartz-daemon")
> > > .log("QUARTZ")
> > > .process(processorName) // trivial, creates arrays with
> > 2-3
> > > random Int
> > > .marshal()
> > > .json(JsonLibrary.Jackson)
> > > .to("mock:end")
> > >
> > > Am I missing some specific Camel-Quartz configuration that would cause
> > > these misfires?
> > >
> > > I would like the scheduler to respect the interval, is this a Quartz
> > issue?
> > >
> > > Am I missing some specific misfire configuration that deals with these
> > > cases?
> > >
> >
>
>
> --
> Best regards,
> *Santiago Acosta Arreaza*
>
> Intermodal Telematics S.L.
> Prisma building, 1st floor, Office 1.5
> Fotógrafo José Norberto Rguez. Díaz st., 2
> San Cristobal de La Laguna, SC de Tenerife
> 38204, Spain
>
>
> +34 922 31 56 05
> www.intermodaltelematics.com
--
Claus Ibsen
-----------------
http://davsclaus.com @davsclaus
Camel in Action 2: https://www.manning.com/ibsen2
Re: camel-quartz is misfiring on startup
Posted by Santiago Acosta <sa...@intermodaltelematics.com>.
Thanks for the info Karen, but I am sad to say we had to move on to use
something else (I think VertX which also has integrations with Camel). I'll
keep this close to the chest when the opportunity to use Camel+Quartz comes
around again.
I'll keep an eye on https://issues.apache.org/jira/browse/CAMEL-17446
On Thu, Jan 6, 2022 at 4:25 PM Karen Lease <ka...@gmail.com> wrote:
> Hi Santiago,
>
> Sorry for the late reply, but it seems no one else picked up on this yet.
> I think the behavior you see is related to the time between the creation
> of the job trigger in Quartz and when Camel finishes initializing and
> the Quartz scheduler is actually started.
>
> The initial fire time of the trigger for your job is set to the time
> when the trigger is created, not when the Quartz scheduler is actually
> started.
> Based on your logs and the Camel Quartz code, the trigger is created
> between the following 2 log messages, so between 19:54:47,514 and 47,545.
>
> > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > scheduler version: 2.3.2
> > ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> > Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> > jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> > 19:54:47 WET 2021
>
> Unfortunately the last message does not show the milliseconds in the
> start date, but we can see it is sometime in the second 19:54:47.
>
> It takes another 435 ms for Camel to finish its work and actually start
> the Quartz scheduler at 19:54:47,980:
> > ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> > scheduler.
> > ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> > DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
>
> Quartz fires the first event as soon as possible since the start time
> has already passed:
> > ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
>
> Adding 1200 ms to the possible start time range, the second one should
> have fired between 19:54:48,714 and 48,745 and it is fired at 48,722.
> > ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
>
>
> Set the logging level to DEBUG on
> org.apache.camel.component.quartz.QuartzEndpoint to see more details
> about the trigger creation but the behavior seems consistent.
>
> Unfortunately, if I correctly understand the code, setting
> triggerStartDelay to a postive number to account for the delay in
> starting the scheduler does not appear to work, since it sets the start
> time of the trigger only if it is *less* than 0 which seems
> counter-intuitive.
>
> In QuartzEndpoint.createTrigger():
> if (getComponent().getScheduler().isStarted() || triggerStartDelay < 0) {
> triggerBuilder.startAt(new Date(System.currentTimeMillis() +
> triggerStartDelay));
> }
>
> I hope this helps or at least explains the behavior.
> I created https://issues.apache.org/jira/browse/CAMEL-17446 related to
> the points I mentioned.
>
>
>
> On 16/12/2021 21:20, Santiago Acosta wrote:
> > Camel 3.13 (but I also tried 3.6 and results are worse)
> >
> > I have an issue where a quartz route is misfiring at the beginning of the
> > startup. I ran some standalone Quartz scheduler with a simple job and
> > trigger and it works as expected, even with a small interval (<200ms).
> >
> > In the case of Camel, the interval is not being respected in the first
> few
> > exchanges.
> >
> > Notice at the end of the log how the first QUARTZ log entries are piled
> > together (interval 1200). If I shorten the interval I can pile them up
> even
> > more (3 entries in 100ms with interval 200ms)
> >
>
> > ...:47,318 INFO [main ] o.q.simpl.SimpleThreadPool - Job
> execution
> > threads will use class loader of thread: main
> > ...:47,332 INFO [main ] o.q.core.SchedulerSignalerImpl - Initialized
> > Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
> > ...:47,333 INFO [main ] o.quartz.core.QuartzScheduler - Quartz
> > Scheduler v.2.3.2 created.
> > ...:47,334 INFO [main ] org.quartz.simpl.RAMJobStore - RAMJobStore
> > initialized.
> > ...:47,514 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> > meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler-camel-1'
> with
> > instanceId 'NON_CLUSTERED'
> > Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
> > NOT STARTED.
> > Currently in standby mode.
> > Number of jobs executed: 0
> > Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10
> threads.
> > Using job-store 'org.quartz.simpl.RAMJobStore' - which does not
> support
> > persistence. and is not clustered.
> >
> > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > scheduler 'DefaultQuartzScheduler-camel-1' initialized from an externally
> > provided properties instance.
> > ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> > scheduler version: 2.3.2
> > ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> > Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> > jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> > 19:54:47 WET 2021
>
> > ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> > scheduler.
> > ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> > DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
> > ...:47,993 INFO [main ] o.a.c.c.mock.MockEndpoint - Asserting:
> > mock://end is satisfied
> > ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
> > ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
> > ...:49,923 INFO [Worker-3] quartz-daemon - QUARTZ
> > ...:51,122 INFO [Worker-4] quartz-daemon - QUARTZ
> > ...:52,321 INFO [Worker-5] quartz-daemon - QUARTZ
> > ...:53,523 INFO [Worker-6] quartz-daemon - QUARTZ
> > ...:54,526 INFO [main ] o.a.c.c.mock.MockEndpoint -
> Re-asserting:
> > mock://end is satisfied after 1000 millis
> >
> > The route I am using is incredibly simple
> >
> >
> >
> from("quartz:resolver?trigger.repeatInterval=1200&stateful=true&triggerStartDelay=0")
> > .id("quartz-daemon")
> > .log("QUARTZ")
> > .process(processorName) // trivial, creates arrays with
> 2-3
> > random Int
> > .marshal()
> > .json(JsonLibrary.Jackson)
> > .to("mock:end")
> >
> > Am I missing some specific Camel-Quartz configuration that would cause
> > these misfires?
> >
> > I would like the scheduler to respect the interval, is this a Quartz
> issue?
> >
> > Am I missing some specific misfire configuration that deals with these
> > cases?
> >
>
--
Best regards,
*Santiago Acosta Arreaza*
Intermodal Telematics S.L.
Prisma building, 1st floor, Office 1.5
Fotógrafo José Norberto Rguez. Díaz st., 2
San Cristobal de La Laguna, SC de Tenerife
38204, Spain
+34 922 31 56 05
www.intermodaltelematics.com
Re: camel-quartz is misfiring on startup
Posted by Karen Lease <ka...@gmail.com>.
Hi Santiago,
Sorry for the late reply, but it seems no one else picked up on this yet.
I think the behavior you see is related to the time between the creation
of the job trigger in Quartz and when Camel finishes initializing and
the Quartz scheduler is actually started.
The initial fire time of the trigger for your job is set to the time
when the trigger is created, not when the Quartz scheduler is actually
started.
Based on your logs and the Camel Quartz code, the trigger is created
between the following 2 log messages, so between 19:54:47,514 and 47,545.
> ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> scheduler version: 2.3.2
> ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> 19:54:47 WET 2021
Unfortunately the last message does not show the milliseconds in the
start date, but we can see it is sometime in the second 19:54:47.
It takes another 435 ms for Camel to finish its work and actually start
the Quartz scheduler at 19:54:47,980:
> ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> scheduler.
> ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
Quartz fires the first event as soon as possible since the start time
has already passed:
> ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
Adding 1200 ms to the possible start time range, the second one should
have fired between 19:54:48,714 and 48,745 and it is fired at 48,722.
> ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
Set the logging level to DEBUG on
org.apache.camel.component.quartz.QuartzEndpoint to see more details
about the trigger creation but the behavior seems consistent.
Unfortunately, if I correctly understand the code, setting
triggerStartDelay to a postive number to account for the delay in
starting the scheduler does not appear to work, since it sets the start
time of the trigger only if it is *less* than 0 which seems
counter-intuitive.
In QuartzEndpoint.createTrigger():
if (getComponent().getScheduler().isStarted() || triggerStartDelay < 0) {
triggerBuilder.startAt(new Date(System.currentTimeMillis() +
triggerStartDelay));
}
I hope this helps or at least explains the behavior.
I created https://issues.apache.org/jira/browse/CAMEL-17446 related to
the points I mentioned.
On 16/12/2021 21:20, Santiago Acosta wrote:
> Camel 3.13 (but I also tried 3.6 and results are worse)
>
> I have an issue where a quartz route is misfiring at the beginning of the
> startup. I ran some standalone Quartz scheduler with a simple job and
> trigger and it works as expected, even with a small interval (<200ms).
>
> In the case of Camel, the interval is not being respected in the first few
> exchanges.
>
> Notice at the end of the log how the first QUARTZ log entries are piled
> together (interval 1200). If I shorten the interval I can pile them up even
> more (3 entries in 100ms with interval 200ms)
>
> ...:47,318 INFO [main ] o.q.simpl.SimpleThreadPool - Job execution
> threads will use class loader of thread: main
> ...:47,332 INFO [main ] o.q.core.SchedulerSignalerImpl - Initialized
> Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
> ...:47,333 INFO [main ] o.quartz.core.QuartzScheduler - Quartz
> Scheduler v.2.3.2 created.
> ...:47,334 INFO [main ] org.quartz.simpl.RAMJobStore - RAMJobStore
> initialized.
> ...:47,514 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> meta-data: Quartz Scheduler (v2.3.2) 'DefaultQuartzScheduler-camel-1' with
> instanceId 'NON_CLUSTERED'
> Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
> NOT STARTED.
> Currently in standby mode.
> Number of jobs executed: 0
> Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 10 threads.
> Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support
> persistence. and is not clustered.
>
> ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> scheduler 'DefaultQuartzScheduler-camel-1' initialized from an externally
> provided properties instance.
> ...:47,514 INFO [main ] o.q.impl.StdSchedulerFactory - Quartz
> scheduler version: 2.3.2
> ...:47,545 INFO [main ] o.a.c.c.quartz.QuartzEndpoint - Job
> Camel_camel-1.resolver (triggerType=SimpleTriggerImpl,
> jobClass=StatefulCamelJob) is scheduled. Next fire date is Thu Dec 16
> 19:54:47 WET 2021
> ...:47,979 INFO [main ] o.a.c.c.quartz.QuartzComponent - Starting
> scheduler.
> ...:47,980 INFO [main ] o.quartz.core.QuartzScheduler - Scheduler
> DefaultQuartzScheduler-camel-1_$_NON_CLUSTERED started.
> ...:47,993 INFO [main ] o.a.c.c.mock.MockEndpoint - Asserting:
> mock://end is satisfied
> ...:48,027 INFO [Worker-1] quartz-daemon - QUARTZ
> ...:48,722 INFO [Worker-2] quartz-daemon - QUARTZ
> ...:49,923 INFO [Worker-3] quartz-daemon - QUARTZ
> ...:51,122 INFO [Worker-4] quartz-daemon - QUARTZ
> ...:52,321 INFO [Worker-5] quartz-daemon - QUARTZ
> ...:53,523 INFO [Worker-6] quartz-daemon - QUARTZ
> ...:54,526 INFO [main ] o.a.c.c.mock.MockEndpoint - Re-asserting:
> mock://end is satisfied after 1000 millis
>
> The route I am using is incredibly simple
>
>
> from("quartz:resolver?trigger.repeatInterval=1200&stateful=true&triggerStartDelay=0")
> .id("quartz-daemon")
> .log("QUARTZ")
> .process(processorName) // trivial, creates arrays with 2-3
> random Int
> .marshal()
> .json(JsonLibrary.Jackson)
> .to("mock:end")
>
> Am I missing some specific Camel-Quartz configuration that would cause
> these misfires?
>
> I would like the scheduler to respect the interval, is this a Quartz issue?
>
> Am I missing some specific misfire configuration that deals with these
> cases?
>