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?
