Problem with simple process

[fwachs]

Hi all,

I'm having a hard time with a really simple process.
It's got a timer start event, then the process runs perfectly. The problem is that once it's done .. it runs it again! and again and again.

[img]https://s3.amazonaws.com/zukbox-test/resources/problem2.png[/img]

What could be causing this problem? It's the only timer start event that has this problem, all of the others are working perfectly.

Thanks,
Federico

[frederikherema1]

How did you specify your timer-event definition?


Example: process will start 4 times, in 5 minute intervals, starting on 11th march 2011, 12:13

        <startEvent id="theStart">
            <timerEventDefinition>
                <timeCycle>R4/2011-03-11T12:13/PT5M</timeCycle>
            </timerEventDefinition>
        </startEvent>
          
Example: process will start once, on selected date

        <startEvent id="theStart">
            <timerEventDefinition>
                <timeDate>2011-03-11T12:13:14</timeDate>
            </timerEventDefinition>
        </startEvent>
          


[fwachs]

I have just realized that this is happening to all of my process with timer start events.


<startEvent id="InicioViajeros" name="Inicio de proceso de viajeros - 15 PM">
      <timerEventDefinition>
        <timeCycle>R1000/2012-12-11T15:00:00-03/P1D</timeCycle>
      </timerEventDefinition>
    </startEvent>

It seems the timer runs, then a new one gets created with the same time the previous one should have ran. For example, a timer should trigger at 1pm on 12/21/2012 , it gets executed and a new timer gets created with a trigger date of 1pm 12/21/2012 instead of 12/22/2012 at 1pm…

I'm on activiti 5.11. I'm forced to shut down activiti in prod environment because of this and to eliminate the jobs by hand in the database. Worst case scenario here

I used to have the explorer and the rest deployed on the same server and that caused trouble before, i removed the rest webapp and everything started working like it should, everything but this timer thing.

I had to remove by hand a few jobs from the jobs table, maybe i screwed the db?

I'm TOTALLY LOST

[jbarrez]

<timeCycle>R1000/2012-12-11T15:00:00-03/P1D</timeCycle>

If you use a timeCYCLE it is indeed expected that a new timer is created every time the timer fires.
Use timeDate or timeDuration otherwise.

[fwachs]

I want it to create a new timer, that's perfect. I want to run this process every day at a certain time for 1000 times.
That's why I used time cycle. But the problem is that the new timer being created is not being set the correct time which would be +1 day, as stated on my timer.

[fwachs]

Any ideas? This continues to be a problem on prod and it's been turned off ever since …
I am out of ideas on why this doesn't work, seems to work best when the number of subprocesses created are not many ( 1 or 2) and it starts working bad with +200.

Once i kill activiti since the it's not working like it should, the timer on the db is left like this:

select * from ACT_RU_JOB where HANDLER_CFG_<>'VerificarExistenciaSuscripcionTrial';

ID_ REV_ TYPE_ LOCK_EXP_TIME_ LOCK_OWNER_ EXCLUSIVE_ EXECUTION_ID_ PROCESS_INSTANCE_ID_ PROC_DEF_ID_ RETRIES_ EXCEPTION_STACK_ID_ EXCEPTION_MSG_ DUEDATE_ REPEAT_ HANDLER_TYPE_ HANDLER_CFG_
349640 8 timer 2012-12-22 14:05:00 64e9e6c3-d0fd-4994-b126-42dfd44f26ee 1 NULL NULL NULL 1 NULL NULL 2012-12-22 13:30:00 0 30 13 * * ? timer-start-event EnvioMensajesSinR

It is also throwing

SEVERE: Error while closing command context
org.activiti.engine.ActivitiOptimisticLockingException: TimerEntity[349640] was updated by another transaction concurrently
        at org.activiti.engine.impl.db.DbSqlSession$DeletePersistentObjectOperation.execute(DbSqlSession.java:238)
        at org.activiti.engine.impl.db.DbSqlSession.flushDeletes(DbSqlSession.java:667)
        at org.activiti.engine.impl.db.DbSqlSession.flush(DbSqlSession.java:461)
        at org.activiti.engine.impl.interceptor.CommandContext.flushSessions(CommandContext.java:167)
        at org.activiti.engine.impl.interceptor.CommandContext.close(CommandContext.java:114)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:69)
        at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:42)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:40)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:32)
        at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:46)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:679)
Exception in thread "pool-1-thread-5" org.activiti.engine.ActivitiOptimisticLockingException: TimerEntity[349640] was updated by another transaction concurrently
        at org.activiti.engine.impl.db.DbSqlSession$DeletePersistentObjectOperation.execute(DbSqlSession.java:238)

It seems there's a problem with the revisions of that timer…it ran 8 times when it only had to run once and then be erased, to leave room for a new timer to be created afterward with a new execution date ( +1 day , if you check the cron expression), but activiti keeps adding revisions and firing the same timer ad eternum.


// It only makes sense to check for optimistic locking exceptions for objects that actually have a revision
      if (persistentObject instanceof HasRevision) {
        int nrOfRowsDeleted = sqlSession.delete(deleteStatement, persistentObject);
        if (nrOfRowsDeleted == 0) {
          throw new ActivitiOptimisticLockingException(DbSqlSession.this.toString(persistentObject) + " was updated by another transaction concurrently");
        }
      } else {
        sqlSession.delete(deleteStatement, persistentObject);
      }

I'm not sure how , but it seems the revision are the problem here:


<!– JOB DELETE STATEMENTS–>

  <delete id="deleteJob" parameterType="org.activiti.engine.impl.persistence.entity.JobEntity">
    delete from ${prefix}ACT_RU_JOB where ID_ = #{id} and REV_ = #{revision}
  </delete>
 
  <delete id="deleteTimer" parameterType="org.activiti.engine.impl.persistence.entity.JobEntity">
    delete from ${prefix}ACT_RU_JOB where ID_ = #{id} and REV_ = #{revision}
  </delete>
 
  <delete id="deleteMessage" parameterType="org.activiti.engine.impl.persistence.entity.JobEntity">
    delete from ${prefix}ACT_RU_JOB where ID_ = #{id} and REV_ = #{revision}
  </delete>

Ok, i've modified those scritps and it didn't work, it still keeps running for eternity.
Maybe this is not working correctly?


@Override
  public void execute(CommandContext commandContext) {

    super.execute(commandContext);

    if (repeat == null) {

      if (log.isLoggable(Level.FINE)) {
        log.fine("Timer " + getId() + " fired. Deleting timer.");
      }
      delete();
    } else {
      delete();
      Date newTimer = calculateRepeat();
      if (newTimer != null) {
        TimerEntity te = new TimerEntity(this);
        te.setDuedate(newTimer);
        Context
            .getCommandContext()
            .getJobManager()
            .schedule(te);
      }
    }

  }

  private Date calculateRepeat() {
    BusinessCalendar businessCalendar = Context
        .getProcessEngineConfiguration()
        .getBusinessCalendarManager()
        .getBusinessCalendar(CycleBusinessCalendar.NAME);
    return businessCalendar.resolveDuedate(repeat);
  }

I'll debug as well as I can though. But some help would be greatly appreciated, what i'm doing is pretty simple, I don't understand how it can be so difficult.

[fwachs]

I've continued doing testing with no luck, when restarting or re-deploying the processes start working like they should. This is only getting stranger.

What concerns me is, what could it possibly make that a job revision field gets incremented and the timer won't be erased to be replaced by another one using the code on TimerEntity.execute() ??
I am trying to follow the code but it's huge. Any hints are appreciated.

[trademak]

Hi,

I've created a unit test with your start event timer definition, and it's working like it's supposed to for me.
So when a job is executed, a new job is created for the next day. Could you create a unit test that shows your problem.
Also, please update your post about the classloading exception (http://forums.activiti.org/en/viewtopic.php?t=5754). Other forum users might be interested in what caused this issue.

Best regards,

[fwachs]

This is not a problem that is easily reproduced, so far I can only reproduce it by leaving the jobs to their own good, with +24h of running without interrumptions and that's when it begins to ocurr. The new timer does not get created and instead the revisions field gets incremented everytime the timer gets executed.

Can you think of a way that something like that could happen?

I'll update the other thread, sure.

[trademak]

Okay, does the job succeed or does it run into an error (OptimisticLockingException for example)?
How long does the job need to execute? Is it only starting a process instance and executing a few automatic service tasks that run very quickly? Or does starting the process instance take very long (> 30 seconds) ?

Best regards,