Task deadline timers are not removed in multi-node setup and fire repeatedly

Issue

• The following sequence of events can lead to stale timer entries in the JBOSS_EJB_TIMER table:

  • Start a process on node1;
  • The process reaches a human task node with notifications/reassignments and creates timers;
  • Complete the task on node2 before the timers are refreshed;

• Timer entries fail to get removed:

  2021-04-01 08:27:44,849 DEBUG [org.jbpm.services.ejb.timer.EJBTimerScheduler] (default task-2) Job handle EjbGlobalJobHandle [uuid=20857_23_START] does not match any timer on org.jbpm.services.ejb.timer.EJBTimerScheduler@5eb65329 scheduler service
  

• Once the notification/reassignment timer expires, it will be called repeatedly as below and the only way to end this is by stopping the node and manually deleting the timer from the timer table.

  2021-04-01 08:29:13,854 WARN  [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 1) Execution of time failed Interval Trigger failed. Skipping GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_START]]
  2021-04-01 08:29:13,865 WARN  [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 4) Execution of time failed Interval Trigger failed. Skipping GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_START]]
  2021-04-01 08:29:13,882 WARN  [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 3) Execution of time failed Interval Trigger failed. Skipping GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_START]]
  2021-04-01 08:29:13,893 WARN  [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 2) Execution of time failed Interval Trigger failed. Skipping GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_START]]
  

• The timer entry is not deleted upon process termination and the EJBTimerScheduler runs in a loop trying to reschedule this already expired timer and the following gets repeated in a loop:

  // SessionNotFound exception
  
  // EJBTimerScheduler.recoverTimerJobInstance method reschedules the timer:
  15:37:21,811 WARN  [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 1) Execution of time failed Interval Trigger failed. Skipping GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_END]]
  
  // timer expiration date is already in the past:
  15:37:21,811 DEBUG [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 1) Timer expiration date is Mon Mar 29 13:13:39 GMT 2021
  
  // a new timer entry is created by the EJB timer subsystem:
  15:37:21,803 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 5) Scheduling a single action timer [id=2a2e919f-45f0-951b-4e1a-df6cc3a5afe0 timedObjectId=ROOT.ROOT.EJBTimerScheduler auto-timer?:false persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@645fcef previousRun=null initialExpiration=Mon Mar 29 13:13:39 GMT 2021 intervalDuration(in milli sec)=0 nextExpiration=Mon Mar 29 13:13:39 GMT 2021 timerState=ACTIVE info=EjbTimerJob [timerJobInstance=GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_END]]]] starting at 0 milliseconds from now
  
  // the timer gets executed immediately:
  15:37:21,804 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 1) Timer task invoked at: Mon Mar 29 15:37:21 GMT 2021 for timer [id=2a2e919f-45f0-951b-4e1a-df6cc3a5afe0 timedObjectId=ROOT.ROOT.EJBTimerScheduler auto-timer?:false persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@645fcef previousRun=null initialExpiration=Mon Mar 29 13:13:39 GMT 2021 intervalDuration(in milli sec)=0 nextExpiration=Mon Mar 29 13:13:39 GMT 2021 timerState=ACTIVE info=EjbTimerJob [timerJobInstance=GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_END]]]]
  
  // timer gets executed in jBPM
  15:37:21,808 DEBUG [org.jbpm.services.ejb.timer.EJBTimerScheduler] (EJB default - 1) About to execute timer for job EjbTimerJob [timerJobInstance=GlobalJpaTimerJobInstance [timerServiceId=project_reproducer_1.0.0-SNAPSHOT-timerServiceId, getJobHandle()=EjbGlobalJobHandle [uuid=20857_23_END]]]
  
  // SessionNotFound exception