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

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major 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

      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.

        1. 01793010_quartz_concurrent_mysql_BPMS640.zip
          36 kB
        2. 01793010_quartz_concurrent_mysql_BPMS614_shortInterval.zip
          19 kB

              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

                Created:
                Updated:
                Resolved: