Quartz misfire policy bug

metabase_quartz.clj

;; NOTE: need to update org.quartz.threadPool.threadCount to 1 in resources/quartz.properties

(require
 '[metabase.task :as task]
 '[metabase.util.log :as log]
 '[metabase.test :as mt]
 '[clojurewerkz.quartzite.scheduler :as qs]
 '[clojurewerkz.quartzite.conversion :as qc]
 '[clojurewerkz.quartzite.matchers  :as quart.match]
 '[clojurewerkz.quartzite.jobs :as jobs]
 '[clojurewerkz.quartzite.schedule.cron :as cron]
 '[clojurewerkz.quartzite.schedule.simple :as schedule.simple]
 '[clojurewerkz.quartzite.schedule.calendar-interval :as calendar-interval]
 '[clojurewerkz.quartzite.triggers :as triggers])

(mt/set-ns-log-level! :info)

(jobs/defjob LongRunningJob [context]
  [context]
  (log/infof "Long job starts: %s" context)
  (Thread/sleep 4000)
  (log/info "Long job is DONE"))

(jobs/defjob PeriodicJob [context]
  [context]
  (log/infof "Periodic job: %s" context))

(let [long-running-job-key (jobs/key "long-running-job.job")
      periodic-job-key     (jobs/key "periodic-job.job")]
  (task/schedule-task! (jobs/build
                        (jobs/of-type LongRunningJob)
                        (jobs/with-identity long-running-job-key))
                       (triggers/build
                        (triggers/with-identity (triggers/key "long.running.job.trigger"))
                        (triggers/start-now)
                        (triggers/for-job long-running-job-key)))
  (task/schedule-task! (jobs/build
                        (jobs/of-type PeriodicJob)
                        (jobs/with-identity periodic-job-key))
                       (triggers/build
                        (triggers/with-identity (triggers/key "periodic.job.trigger"))
                        (triggers/for-job periodic-job-key)
                        (triggers/with-schedule
                          #_(cron/schedule
                             ;; run every 2 seconds
                             (cron/cron-schedule "*/2 0/1 * 1/1 * ? *")
                             (cron/with-misfire-handling-instruction-fire-and-proceed))
                          (schedule.simple/schedule
                           (schedule.simple/with-repeat-count 100)
                           (schedule.simple/with-interval-in-seconds 1)
                           (schedule.simple/with-misfire-handling-instruction-next-with-remaining-count))
                          #_(calendar-interval/schedule
                             (calendar-interval/with-interval-in-seconds 2)
                             (calendar-interval/with-misfire-handling-instruction-fire-and-proceed))))))

;; 2024-05-03 07:35:09,596 INFO pulse-task :: Long job starts: JobExecutionContext: trigger: 'DEFAULT.long.running.job.trigger job: DEFAULT.long-running-job.job fireTime: 'Fri May 03 07:35:09 UTC 2024 scheduledFireTime: Fri May 03 07:35:09 UTC 2024 previousFireTime: 'null nextFireTime: null isRecovering: false refireCount: 0
;; 2024-05-03 07:35:13,603 INFO pulse-task :: Long job is DONE
;; 2024-05-03 07:35:13,617 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:13 UTC 2024 scheduledFireTime: Fri May 03 07:35:10 UTC 2024 previousFireTime: 'null nextFireTime: Fri May 03 07:35:12 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:13,625 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:13 UTC 2024 scheduledFireTime: Fri May 03 07:35:12 UTC 2024 previousFireTime: 'Fri May 03 07:35:10 UTC 2024 nextFireTime: Fri May 03 07:35:14 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:14,011 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:14 UTC 2024 scheduledFireTime: Fri May 03 07:35:14 UTC 2024 previousFireTime: 'Fri May 03 07:35:12 UTC 2024 nextFireTime: Fri May 03 07:35:16 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:16,013 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:16 UTC 2024 scheduledFireTime: Fri May 03 07:35:16 UTC 2024 previousFireTime: 'Fri May 03 07:35:14 UTC 2024 nextFireTime: Fri May 03 07:35:18 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:18,014 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:18 UTC 2024 scheduledFireTime: Fri May 03 07:35:18 UTC 2024 previousFireTime: 'Fri May 03 07:35:16 UTC 2024 nextFireTime: Fri May 03 07:35:20 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:20,008 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:20 UTC 2024 scheduledFireTime: Fri May 03 07:35:20 UTC 2024 previousFireTime: 'Fri May 03 07:35:18 UTC 2024 nextFireTime: Fri May 03 07:35:22 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:22,018 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:22 UTC 2024 scheduledFireTime: Fri May 03 07:35:22 UTC 2024 previousFireTime: 'Fri May 03 07:35:20 UTC 2024 nextFireTime: Fri May 03 07:35:24 UTC 2024 isRecovering: false refireCount: 0
;; 2024-05-03 07:35:24,015 INFO pulse-task :: Periodic job: JobExecutionContext: trigger: 'DEFAULT.periodic.job.trigger job: DEFAULT.periodic-job.job fireTime: 'Fri May 03 07:35:24 UTC 2024 scheduledFireTime: Fri May 03 07:35:24 UTC 2024 previousFireTime: 'Fri May 03 07:35:22 UTC 2024 nextFireTime: Fri May 03 07:35:26 UTC 2024 isRecovering: false refireCount: 0

the timing of the Periodic job log suggests that right after a long job is done, 2 misfired periodic jobs are fired; we should only trigger one, tho.