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

Job/Trigger for repeat Timer are deleted on short interval executions with Quartz

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 7.0.0.GA
    • None
    • jBPM Core
      • BPMS 6.1.4, 6.4.0, jBPM 7.1.0-SNAPSHOT
      • Quartz 1.8.5
      • MySQL, Oracle
    • Hide

      See Description

      Show
      See Description
    • jBPM sprint 2, jBPM sprint 3

    Description

      If 2 Triggers for the same Job (e.g. StartTimerEvent with timeCycle) are executed with short interval, the Job/Trigger could be deleted in Quartz tables so StartTimerEvent is no longer triggered.

      Try attached reproducer 01793010_quartz_concurrent_mysql_BPMS640.zip

      • Edit StartTimerTest.java and quartz-definition.properties for your database settings
      • Create Quartz tables. This test makes sure to truncate the tables on test.
      • mvn clean test
      • This test uses Byteman to simulate the race condition that Worker-1 is executing JobStoreSupport.triggeredJobComplete() and Worker-2 is executing jBPM process.
      2017-04-26 17:45:43,293[jBPMClusteredScheduler_Worker-1] --- Process started : piid = 1
2017-04-26 17:45:43,330 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,331 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,332 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,335 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,336 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,337 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,340 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,345 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_Worker-1
2017-04-26 17:45:43,382 DEBUG [jBPMClusteredScheduler_Worker-1] [org.jbpm.persistence.timer.GlobalJpaTimerJobInstance] Allowed to dispose command service from global timer job instance
2017-04-26 17:45:43,383 DEBUG [jBPMClusteredScheduler_Worker-1] [org.jbpm.runtime.manager.impl.PerProcessInstanceRuntimeManager] Removing lock java.util.concurrent.locks.ReentrantLock@6acc79da[Locked by thread jBPMClusteredScheduler_Worker-1] from list as non is waiting for it by org.jbpm.runtime.manager.impl.RuntimeEngineImpl@22026f95
2017-04-26 17:45:43,383 DEBUG [jBPMClusteredScheduler_Worker-1] [org.jbpm.runtime.manager.impl.PerProcessInstanceRuntimeManager] java.util.concurrent.locks.ReentrantLock@6acc79da[Unlocked] unlocked by org.jbpm.runtime.manager.impl.RuntimeEngineImpl@22026f95
[jBPMClusteredScheduler_Worker-1] triggeredJobComplete() entry. Wait for next job
2017-04-26 17:45:54,853 DEBUG [QuartzScheduler_jBPMClusteredScheduler-tkobayas.nrt.csb1493196332781_ClusterManager] [org.quartz.impl.jdbcjobstore.JobStoreCMT] ClusterManager: Check-in complete.
2017-04-26 17:46:07,096 DEBUG [jBPMClusteredScheduler_QuartzSchedulerThread] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_QuartzSchedulerThread
2017-04-26 17:46:07,097 DEBUG [jBPMClusteredScheduler_QuartzSchedulerThread] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_QuartzSchedulerThread
2017-04-26 17:46:07,098 DEBUG [jBPMClusteredScheduler_QuartzSchedulerThread] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_QuartzSchedulerThread
2017-04-26 17:46:07,108 DEBUG [jBPMClusteredScheduler_QuartzSchedulerThread] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_QuartzSchedulerThread
2017-04-26 17:46:07,108 DEBUG [jBPMClusteredScheduler_QuartzSchedulerThread] [org.quartz.simpl.SimpleJobFactory] Producing instance of Job 'jbpm.StartProcess-com.sample.bpmn.hello-1', class=org.jbpm.process.core.timer.impl.QuartzSchedulerService$QuartzJob
2017-04-26 17:46:07,109 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.core.JobRunShell] Calling execute on job jbpm.StartProcess-com.sample.bpmn.hello-1
2017-04-26 17:46:07,118 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] Scheduling timer with name StartProcess-com.sample.bpmn.hello-1
2017-04-26 17:46:07,123 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.process.core.timer.impl.GlobalTimerService] Returning  timers [GlobalJpaTimerJobInstance [timerServiceId=default-per-pinstance-timerServiceId, getJobHandle()=GlobalQuartzJobHandle [jobName=StartProcess-com.sample.bpmn.hello-1, jobGroup=jbpm]]] for session 3
2017-04-26 17:46:07,132 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.services.task.persistence.TaskTransactionInterceptor] Instantiating JtaTransactionManager
[jBPMClusteredScheduler_Worker-2] StartProcessJob.execute() entry. Signaling...
[jBPMClusteredScheduler_Worker-1] wake up!
2017-04-26 17:46:07,150 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_Worker-1
2017-04-26 17:46:07,150 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_Worker-1
2017-04-26 17:46:07,151 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_Worker-1
2017-04-26 17:46:07,156 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.JobStoreCMT] Deleting job: jbpm.StartProcess-com.sample.bpmn.hello-1
2017-04-26 17:46:07,157 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.runtime.manager.impl.PerProcessInstanceRuntimeManager] [MaintainMappingListener] Lock java.util.concurrent.locks.ReentrantLock@7d807043[Locked by thread jBPMClusteredScheduler_Worker-2] created and stored in list by org.jbpm.runtime.manager.impl.RuntimeEngineImpl@68205b49
2017-04-26 17:46:07,160[jBPMClusteredScheduler_Worker-2] --- Process started : piid = 2
2017-04-26 17:46:07,161 DEBUG [jBPMClusteredScheduler_Worker-1] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_Worker-1
2017-04-26 17:46:07,180 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,180 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,180 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,185 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,185 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,186 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,186 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,189 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,189 WARN  [jBPMClusteredScheduler_Worker-2] [org.jbpm.process.core.timer.impl.QuartzSchedulerService] Job has already been scheduled, most likely running in cluster: Unable to store Trigger with name: 'StartProcess-com.sample.bpmn.hello-1_trigger' and group: 'jbpm', because one already exists with this identification.
2017-04-26 17:46:07,197 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.persistence.timer.GlobalJpaTimerJobInstance] Allowed to dispose command service from global timer job instance
2017-04-26 17:46:07,199 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.runtime.manager.impl.PerProcessInstanceRuntimeManager] Removing lock java.util.concurrent.locks.ReentrantLock@7d807043[Locked by thread jBPMClusteredScheduler_Worker-2] from list as non is waiting for it by org.jbpm.runtime.manager.impl.RuntimeEngineImpl@68205b49
2017-04-26 17:46:07,199 DEBUG [jBPMClusteredScheduler_Worker-2] [org.jbpm.runtime.manager.impl.PerProcessInstanceRuntimeManager] java.util.concurrent.locks.ReentrantLock@7d807043[Unlocked] unlocked by org.jbpm.runtime.manager.impl.RuntimeEngineImpl@68205b49
2017-04-26 17:46:07,204 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is desired by: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,204 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' is being obtained: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,204 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' given to: jBPMClusteredScheduler_Worker-2
2017-04-26 17:46:07,209 DEBUG [jBPMClusteredScheduler_Worker-2] [org.quartz.impl.jdbcjobstore.StdRowLockSemaphore] Lock 'TRIGGER_ACCESS' returned by: jBPMClusteredScheduler_Worker-2

      I think the problem is here:

      https://github.com/quartz-scheduler/quartz/blob/quartz-1.8.5/quartz/src/main/java/org/quartz/impl/jdbcjobstore/JobStoreSupport.java#L2976-L2983

      In a normal case, "trigger.getNextFireTime() == null" and "stat != null" and "stat.getNextFireTime() != null" so it doesn't fall into removeTrigger().

      In this problem case, the second execution by Worker-2 has updated the stat (= quartz_triggers table) so Worker-1 falls into removeTrigger() (See "Deleting job:" log). So removed the Job/Trigger.

      I guess it's a problem in Quartz side which allows to trigger a Job which is still in progress. But may be a problem of usage in jBPM side?

      Please note that "short interval" is achieved by Byteman in this reproducer. In usual case, it could happen even with 1 minutes timeCycle StartTimerEvent when MisfireHandler is involved. Say, MisfireHandler amends a trigger time and the trigger is fired. Then a newly created Trigger may have very close NextFireTime.

      With H2, I could reproduce "Deleting job:" log but somehow StartTimerEvent keeps working.

      Attachments

        Issue Links

          is cloned by

          Bug - A problem that impairs or prevents the functions of the product. RHBPMS-4724 [GSS] (6.4.z) Job/Trigger for repeat Timer are deleted on short interval executions with Quartz

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Verified
          is related to

          Bug - A problem that impairs or prevents the functions of the product. RHPAM-286 QuartzSchedulerService increments NEXT_FIRE_TIME by timeCycle regardless of current time when calling rescheduleJob()

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Activity

            People

              swiderski.maciej Maciej Swiderski (Inactive)
              rhn-support-tkobayas Toshiya Kobayashi
              Tomáš Livora Tomáš Livora (Inactive)
              Tomáš Livora Tomáš Livora (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: