Uploaded image for project: 'Red Hat Process Automation Manager'
  1. Red Hat Process Automation Manager
  2. RHPAM-286

QuartzSchedulerService increments NEXT_FIRE_TIME by timeCycle regardless of current time when calling rescheduleJob()

    Details

    • Type: Bug
    • Status: Verified (View Workflow)
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: 6.x.x
    • Fix Version/s: 7.0.0.GA
    • Component/s: jBPM Core
    • Labels:
    • Environment:
      • QuartzScheduler

      Description

      QuartzSchedulerService increments NEXT_FIRE_TIME by timeCycle regardless of current time when calling rescheduleJob()

      QuartzSchedulerService increments NEXT_FIRE_TIME by the timeCycle regardless of current time. So if we reboot BPMS with some interval larger than (timeCycle + misfireThreshold), NEXT_FIRE_TIME becomes always older than (now - misfireThreshold).

      In this case, MisfireHandler has to amend the NEXT_FIRE_TIME so the execution cycle always relies on MisfireHandler so cannot be shorter than "misfireThreshold".

      See the attached reproducer 01793010_quartz_misfire_h2_BPMS640.zip.

      • StartTimerEvent timeCycle = 10s
      • misfireThreshold = 60000
      • idleWaitTime = 30000 (default)

      After RuntimeManager restart, you will see StartTimerEvent is triggered only with 60 seconds interval which depends on misfireThreshold.

      Below is the output example with debug logging:

      @@ -171,6 +171,7 @@ public class QuartzSchedulerService implements GlobalSchedulerService {
                       scheduler.addJob(jobq, true);
                       triggerq.setJobName(quartzJobHandle.getJobName());
                       triggerq.setJobGroup(quartzJobHandle.getJobGroup());
      +                logger.info("############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = " + triggerq.getStartTime());
                       scheduler.rescheduleJob(quartzJobHandle.getJobName()+"_trigger", quartzJobHandle.getJobGroup(), triggerq);
                   }
      
      2017-05-12 19:03:24,396 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler meta-data: Quartz Scheduler (v1.8.5) 'jBPMClusteredScheduler' with instanceId 'tkobayas.nrt.csb1494583404379'
        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 5 threads.
        Using job-store 'org.quartz.impl.jdbcjobstore.JobStoreCMT' - which supports persistence. and is clustered.
      
      2017-05-12 19:03:24,396 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler 'jBPMClusteredScheduler' initialized from specified file: 'quartz-definition.properties' in the class resource path.
      2017-05-12 19:03:24,396 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler version: 1.8.5
      2017-05-12 19:03:24,399 INFO  [main] [org.drools.persistence.TransactionManagerFactory] Using org.drools.persistence.jta.JtaTransactionManagerFactory@5e922647
      2017-05-12 19:03:26,421 INFO  [Thread-6] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 started.
      2017-05-12 19:03:34,755[jBPMClusteredScheduler_Worker-1] --- Process started : piid = 1
      2017-05-12 19:03:35,757[jBPMClusteredScheduler_Worker-1] --- work done
      2017-05-12 19:03:35,915 INFO  [jBPMClusteredScheduler_Worker-1] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:03:44 JST 2017
      === closing RuntimeManager
      2017-05-12 19:03:36,948 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 shutting down.
      2017-05-12 19:03:36,949 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 paused.
      2017-05-12 19:03:36,961 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583404379 shutdown complete.
      === sleeping
      === sleep done
      2017-05-12 19:04:57,102 INFO  [main] [org.quartz.core.SchedulerSignalerImpl] Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
      2017-05-12 19:04:57,103 INFO  [main] [org.quartz.core.QuartzScheduler] Quartz Scheduler v.1.8.5 created.
      2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Using db table-based data access locking (synchronization).
      2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.jdbcjobstore.JobStoreCMT] JobStoreCMT initialized.
      2017-05-12 19:04:57,103 INFO  [main] [org.quartz.core.QuartzScheduler] Scheduler meta-data: Quartz Scheduler (v1.8.5) 'jBPMClusteredScheduler' with instanceId 'tkobayas.nrt.csb1494583497101'
        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 5 threads.
        Using job-store 'org.quartz.impl.jdbcjobstore.JobStoreCMT' - which supports persistence. and is clustered.
      
      2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler 'jBPMClusteredScheduler' initialized from specified file: 'quartz-definition.properties' in the class resource path.
      2017-05-12 19:04:57,103 INFO  [main] [org.quartz.impl.StdSchedulerFactory] Quartz scheduler version: 1.8.5
      2017-05-12 19:04:59,127 INFO  [Thread-11] [org.quartz.impl.jdbcjobstore.JobStoreCMT] ClusterManager: detected 1 failed or restarted instances.
      2017-05-12 19:04:59,128 INFO  [Thread-11] [org.quartz.impl.jdbcjobstore.JobStoreCMT] ClusterManager: Scanning for instance "tkobayas.nrt.csb1494583404379"'s failed in-progress jobs.
      2017-05-12 19:04:59,136 INFO  [Thread-11] [org.quartz.core.QuartzScheduler] Scheduler jBPMClusteredScheduler_$_tkobayas.nrt.csb1494583497101 started.
      2017-05-12 19:04:59,152 INFO  [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1494583497101_MisfireHandler] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Handling 1 trigger(s) that missed their scheduled fire-time.
      2017-05-12 19:04:59,214[jBPMClusteredScheduler_Worker-1] --- Process started : piid = 2
      2017-05-12 19:05:00,215[jBPMClusteredScheduler_Worker-1] --- work done
      2017-05-12 19:05:00,269 INFO  [jBPMClusteredScheduler_Worker-1] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:03:54 JST 2017
      2017-05-12 19:05:59,148 INFO  [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1494583497101_MisfireHandler] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Handling 1 trigger(s) that missed their scheduled fire-time.
      2017-05-12 19:05:59,232[jBPMClusteredScheduler_Worker-2] --- Process started : piid = 3
      2017-05-12 19:06:00,233[jBPMClusteredScheduler_Worker-2] --- work done
      2017-05-12 19:06:00,287 INFO  [jBPMClusteredScheduler_Worker-2] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:04:04 JST 2017
      2017-05-12 19:06:59,144 INFO  [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1494583497101_MisfireHandler] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Handling 1 trigger(s) that missed their scheduled fire-time.
      2017-05-12 19:06:59,229[jBPMClusteredScheduler_Worker-3] --- Process started : piid = 4
      2017-05-12 19:07:00,229[jBPMClusteredScheduler_Worker-3] --- work done
      2017-05-12 19:07:00,283 INFO  [jBPMClusteredScheduler_Worker-3] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] ############: about to call scheduler.rescheduleJob(): triggerq.getStartTime() = Fri May 12 19:04:14 JST 2017
      

      You also see that triggerq.getStartTime() is always old.

      I guess QuartzSchedulerService.internalSchedule() should set (now + timeCycle) to SimpleTrigger.startTime.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  swiderski.maciej Maciej Swiderski
                  Reporter:
                  tkobayashi Toshiya Kobayashi
                  Tester:
                  Tomáš Livora
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  4 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: