[jbpm-issues] [JBoss JIRA] Updated: (JBPM-627) Cancel timer problem

Cancel timer problem -------------------- Key: JBPM-627 URL: http://jira.jboss.com/jira/browse/JBPM-627 Project: JBoss jBPM Issue Type: Bug Components: Core Engine Affects Versions: jBPM 3.1 Environment: Windows XP Pro Database: DB2/400 v5r3, HSQLDB Reporter: Mark Shotton Assigned To: Tom Baeyens Fix For: jBPM jPDL 3.2.4 Attachments: JBPM-627-screenshots.doc As reported in issue JBPM-594, timers do not get deleted on the cancel-timer event. This is because in SchedulerSession.cancelTimersByName(String, Token), the timer is deleted by a call to SchedulerSession.deleteTimer: public void deleteTimer(Timer timer) { if (! deletedTimers.contains(timer)) { try { session.delete(timer); deletedTimers.add(timer); } catch (Exception e) { log.error(e); jbpmSession.handleException(); throw new JbpmException("couldn't delete timer '"+timer+"' from the database", e); } } } but in SchedulerThread, the timer is saved again if timer.getRepeat() is not null: public long executeTimers() { long millisTillNextTimerIsDue = -1; boolean isDueDateInPast = true; JbpmContext jbpmContext = jbpmConfiguration.createJbpmContext(jbpmContextName); try { SchedulerSession schedulerSession = jbpmContext.getSchedulerSession(); log.debug("checking for timers"); Iterator iter = schedulerSession.findTimersByDueDate(); while( (iter.hasNext()) && (isDueDateInPast) ) { Timer timer = (Timer) iter.next(); log.debug("found timer "+timer); // if this timer is due if (timer.isDue()) { log.debug("executing timer '"+timer+"'"); // execute timer.execute(); // save the process instance jbpmContext.save(timer.getProcessInstance()); // notify the listeners (e.g. the scheduler servlet) notifyListeners(timer); // if there was an exception, just save the timer if (timer.getException()!=null) { schedulerSession.saveTimer(timer); // if repeat is specified } else if (timer.getRepeat()!=null) { // update timer by adding the repeat duration Date dueDate = timer.getDueDate(); // suppose that it took the timer runner thread a // very long time to execute the timers. // then the repeat action dueDate could already have passed. while (dueDate.getTime()<=System.currentTimeMillis()) { dueDate = businessCalendar .add(dueDate, new Duration(timer.getRepeat())); } timer.setDueDate( dueDate ); // save the updated timer in the database log.debug("saving updated timer for repetition '"+timer+"' in '"+(dueDate.getTime()-System.currentTimeMillis())+"' millis"); schedulerSession.saveTimer(timer); } else { // delete this timer log.debug("deleting timer '"+timer+"'"); schedulerSession.deleteTimer(timer); } } else { // this is the first timer that is not yet due isDueDateInPast = false; millisTillNextTimerIsDue = timer.getDueDate().getTime() - System.currentTimeMillis(); } } } finally { jbpmContext.close(); } A work-around was suggested in JBPM-594: "As workaround now I do remove timer myself in action just before calling signal(): if(flag) { //need to remove scheduler session as it is not removed during event with //cancel-timer element SchedulerSession schsession = ctx.getJbpmContext().getSchedulerSession(); Timer timer=(Timer) schsession.findTimersByName("aaa",ctx.getToken()).get(0); log.info("found timer:"+timer.getName()); timer.setRepeat(null); timer.setSuspended(true); schsession.saveTimer(timer); ctx.getToken().signal("tonode1"); } " However, this does not seem to be thread-safe as the call to findTimersByName sometimes returns a zero-length array and sometimes an exception if the work-around code to cancel the timer executes before the timer is available from the SchedulerSession (and this does happen even when the code to cancel the timer is within the ActionHandler of the timer) As a different work-around, I set the timer repeat to null in the SchedulerSession.deleteTimer method to ensure that it will not be saved again in the SchedulerThread.executeTimers method: public void deleteTimer(Timer timer) { if (! deletedTimers.contains(timer)) { try { session.delete(timer); deletedTimers.add(timer); //MWS 06/04/06 workaround to ensure that timer is deleted timer.setRepeat(null); } catch (Exception e) { log.error(e); jbpmSession.handleException(); throw new JbpmException("couldn't delete timer '"+timer+"' from the database", e); } } } However, this causes an occasional exception to be thrown: org.jbpm.persistence.JbpmPersistenceException: couldn't commit hibernate session at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:171) at org.jbpm.svc.Services.close(Services.java:211) at org.jbpm.JbpmContext.close(JbpmContext.java:138) at org.jbpm.scheduler.impl.SchedulerThread.executeTimers(SchedulerThread.java:161) at org.jbpm.scheduler.impl.SchedulerThread.run(SchedulerThread.java:70) Caused by: org.hibernate.StaleStateException: Unexpected row count: 0 expected: 1 at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:27) at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2204) at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2118) at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:2374) at org.hibernate.action.EntityUpdateAction.execute(EntityUpdateAction.java:84) at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:243) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:227) at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:141) at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:296) at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27) at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:980) at org.hibernate.impl.SessionImpl.managedFlush(SessionImpl.java:353) On further investigation, it appears that on some occasions, when deleting a timer on a cancel-timer event, the call to session.getNamedQuery("SchedulerSession.findTimersByName") causes a hibernate flush to occur which attempts to update a timer that has already been deleted: public void cancelTimersByName(String timerName, Token token) { try { Query query = session.getNamedQuery("SchedulerSession.findTimersByName"); query.setString("timerName", timerName); query.setEntity("token", token); Iterator iter = query.list().iterator(); while(iter.hasNext()) { deleteTimer((Timer) iter.next()); } } catch (Exception e) { log.error(e); jbpmSession.handleException(); throw new JbpmException("couldn't delete timer '"+timerName+"' on '"+token+"' from the database", e); } } I have some screenshots below to illustrate this but cannot include them in this form. The attempt to cancel the timer ?processing_error_task_timer? causes the following query to be issued: <query name="SchedulerSession.findTimersByName"> <![CDATA[ select t from org.jbpm.scheduler.exe.Timer t where t.name = :timerName and t.token = :token ]]> </query> which in turn causes hibernate to flush and attempt to issue the SQL statement: update JBPM_TIMER set NAME_=?, DUEDATE_=?, REPEAT_=?, TRANSITIONNAME_=?, EXCEPTION_=?, ISSUSPENDED_=?, ACTION_=?, TOKEN_=?, PROCESSINSTANCE_=?, TASKINSTANCE_=?, GRAPHELEMENTTYPE_=?, GRAPHELEMENT_=? where ID_=? where the ID_ of the timer is that of a previous timer that has already been deleted from the database called ?credit_referral_task_timer? (I confirmed this by inspection of the JBPM_TIMER table). I am at a loss to explain how the hibernate cache contains a timer that has already been deleted from the database.