Timer fired every 5 minutes while executing a long running command

nchan — Fri, 14 Nov 2014 16:38:48 GMT

Activiti version tested : 5.16 and 5.10I have a simple workflow with a timer catching event and a long running task attached to it.START — TimerCatchingEvent (PT10S Intermediate Event) — ScriptTask (Long running - runs for more than 5 min) — ENDThe script task runs for more than 5 minutes. While th

Re: Timer fired every 5 minutes while executing a long running command

trademak — Fri, 14 Nov 2014 16:47:29 GMT

Could you retest when you make the script task async?

Best regards,

Re: Timer fired every 5 minutes while executing a long running command

nchan — Fri, 14 Nov 2014 17:55:26 GMT

Hi Tijs,

I am still seeing this behavior with script task async turned on.

I tweaked my activiti bpmn to include a listener and print the time and thread id on entry and exit of the timer and the script task. Reposting my new bpmn along with the test console logs.


<?xml version="1.0" encoding="UTF-8"?>
<definitions xmlns="http://www.omg.org/spec/BPMN/20100524/MODEL" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:activiti="http://activiti.org/bpmn" xmlns:bpmndi="http://www.omg.org/spec/BPMN/20100524/DI" xmlns:smileysurprised:mgdc="http://www.omg.org/spec/DD/20100524/DC" xmlns:smileysurprised:mgdi="http://www.omg.org/spec/DD/20100524/DI" typeLanguage="http://www.w3.org/2001/XMLSchema" expressionLanguage="http://www.w3.org/1999/XPath" targetNamespace="http://www.activiti.org/test">
  <process id="myProcess" name="My process" isExecutable="true">
    <startEvent id="startevent1" name="Start"></startEvent>
    <intermediateCatchEvent id="timerintermediatecatchevent3" name="TimerCatchEvent">
      <extensionElements>
        <activiti:executionListener event="start" class="com.cisco.xxx.MyTaskListener"></activiti:executionListener>
        <activiti:executionListener event="end" class="com.cisco.xxx.MyTaskListener"></activiti:executionListener>
      </extensionElements>
      <timerEventDefinition>
        <timeDuration>PT10S</timeDuration>
      </timerEventDefinition>
    </intermediateCatchEvent>
    <sequenceFlow id="flow24" sourceRef="timerintermediatecatchevent3" targetRef="scripttask5"></sequenceFlow>
    <scriptTask id="scripttask5" name="Long running command" activiti:async="true" scriptFormat="groovy" activiti:autoStoreVariables="false">
      <extensionElements>
        <activiti:executionListener event="start" class="com.cisco.xxx.MyTaskListener"></activiti:executionListener>
        <activiti:executionListener event="end" class="com.cisco.xxx.MyTaskListener"></activiti:executionListener>
      </extensionElements>
      <script>println "Running command .."
def y = 5000000

while ( y– &gt; 0 ) {
    def command = """find . -name "*.*" -print"""    
    def proc = command.execute()    
    proc.waitFor()    
    if( y % 50000 == 0) println  Thread.currentThread().getId() + " – " + " Still running …" + y
}
print "Completed running command"</script>
    </scriptTask>
    <sequenceFlow id="flow25" sourceRef="scripttask5" targetRef="endevent2"></sequenceFlow>
    <endEvent id="endevent2" name="End">
      <extensionElements>
        <activiti:executionListener event="start" class="com.cisco.xxx.MyTaskListener"></activiti:executionListener>
      </extensionElements>
    </endEvent>
    <sequenceFlow id="flow26" sourceRef="startevent1" targetRef="timerintermediatecatchevent3"></sequenceFlow>
  </process>
  <bpmndi:BPMNDiagram id="BPMNDiagram_myProcess">
    <bpmndi:BPMNPlane bpmnElement="myProcess" id="BPMNPlane_myProcess">
      <bpmndi:BPMNShape bpmnElement="startevent1" id="BPMNShape_startevent1">
        <omgdc:Bounds height="35.0" width="35.0" x="210.0" y="70.0"></omgdc:Bounds>
      </bpmndi:BPMNShape>
      <bpmndi:BPMNShape bpmnElement="timerintermediatecatchevent3" id="BPMNShape_timerintermediatecatchevent3">
        <omgdc:Bounds height="35.0" width="35.0" x="290.0" y="70.0"></omgdc:Bounds>
      </bpmndi:BPMNShape>
      <bpmndi:BPMNShape bpmnElement="scripttask5" id="BPMNShape_scripttask5">
        <omgdc:Bounds height="71.0" width="105.0" x="360.0" y="52.0"></omgdc:Bounds>
      </bpmndi:BPMNShape>
      <bpmndi:BPMNShape bpmnElement="endevent2" id="BPMNShape_endevent2">
        <omgdc:Bounds height="35.0" width="35.0" x="530.0" y="70.0"></omgdc:Bounds>
      </bpmndi:BPMNShape>
      <bpmndi:BPMNEdge bpmnElement="flow24" id="BPMNEdge_flow24">
        <omgdi:waypoint x="325.0" y="87.0"></omgdi:waypoint>
        <omgdi:waypoint x="360.0" y="87.0"></omgdi:waypoint>
      </bpmndi:BPMNEdge>
      <bpmndi:BPMNEdge bpmnElement="flow25" id="BPMNEdge_flow25">
        <omgdi:waypoint x="465.0" y="87.0"></omgdi:waypoint>
        <omgdi:waypoint x="530.0" y="87.0"></omgdi:waypoint>
      </bpmndi:BPMNEdge>
      <bpmndi:BPMNEdge bpmnElement="flow26" id="BPMNEdge_flow26">
        <omgdi:waypoint x="245.0" y="87.0"></omgdi:waypoint>
        <omgdi:waypoint x="290.0" y="87.0"></omgdi:waypoint>
      </bpmndi:BPMNEdge>
    </bpmndi:BPMNPlane>
  </bpmndi:BPMNDiagram>
</definitions>

My listener:


package com.cisco.xxx;
import java.util.Date;
import java.util.logging.Logger;

import org.activiti.engine.delegate.DelegateExecution;
import org.activiti.engine.delegate.ExecutionListener;

public class MyTaskListener implements ExecutionListener {
 
 private static final long serialVersionUID = 1L;
 private Logger log = Logger.getLogger(MyTaskListener.class.getName());

 @Override
 public void notify(DelegateExecution execution) throws Exception {
  System.out.println("Thread:" + Thread.currentThread().getId() + " event name:" + execution.getEventName() + " – Inside listener for task:id " + execution.getCurrentActivityName() + ":" + execution.getCurrentActivityId() + " ….  @" + new Date() );  
 }

}

Test output:


Nov 14, 2014 9:35:33 AM org.springframework.beans.factory.xml.XmlBeanDefinitionReader loadBeanDefinitions
INFO: Loading XML bean definitions from class path resource [activiti.cfg.xml]
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.db.DbSqlSession executeSchemaResource
INFO: performing create on engine with resource org/activiti/db/create/activiti.h2.create.engine.sql
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.db.DbSqlSession executeSchemaResource
INFO: performing create on history with resource org/activiti/db/create/activiti.h2.create.history.sql
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.db.DbSqlSession executeSchemaResource
INFO: performing create on identity with resource org/activiti/db/create/activiti.h2.create.identity.sql
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.ProcessEngineImpl <init>
INFO: ProcessEngine default created
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.jobexecutor.JobExecutor start
INFO: Starting up the JobExecutor[org.activiti.engine.impl.jobexecutor.DefaultJobExecutor].
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.jobexecutor.AcquireJobsRunnable run
INFO: JobExecutor[org.activiti.engine.impl.jobexecutor.DefaultJobExecutor] starting to acquire jobs
Nov 14, 2014 9:35:35 AM org.activiti.engine.impl.bpmn.deployer.BpmnDeployer deploy
INFO: Processing resource myProcess.bpmn20.xml

Thread:1 event name:start – Inside listener for task:id TimerCatchEvent:timerintermediatecatchevent3 ….  @Fri Nov 14 09:35:37 PST 2014
Thread:22 event name:end – Inside listener for task:id TimerCatchEvent:timerintermediatecatchevent3 ….  @Fri Nov 14 09:35:50 PST 2014

Thread:23 event name:start – Inside listener for task:id null:scripttask5 ….  @Fri Nov 14 09:35:50 PST 2014
Running command ..

Thread:24607 event name:start – Inside listener for task:id null:scripttask5 ….  @Fri Nov 14 09:40:51 PST 2014
Running command ..

Thread:22 event name:start – Inside listener for task:id null:scripttask5 ….  @Fri Nov 14 09:45:52 PST 2014
Running command ..

Re: Timer fired every 5 minutes while executing a long running command

jbarrez — Wed, 19 Nov 2014 23:20:00 GMT

Five minutes seems very long, my guess is that the job executor thinks the jon is stuck and releases it, and then executes it again. You can set the locktime to be higher than 5 minutes.

Re: Timer fired every 5 minutes while executing a long running command

jbarrez — Thu, 20 Nov 2014 08:58:59 GMT

>Activiti team, I request you to capture this behavior either in the user guide or FAQ, please. This would definitely save lot of man hours.

It would be even cooler if you could create a pull request for this 😉 I takes as much time as writing this post 😉 (see http://www.jorambarrez.be/blog/2014/11/05/how-to-create-an-activiti-pull-request/)

The lock time is configurable. However, the approach with the receive task is certainly the more preferred approach.

Re: Timer fired every 5 minutes while executing a long running command

nchan — Thu, 20 Nov 2014 19:13:28 GMT

Thanks for your response. I found out the real issue and a fix for this. Posting it for the benefit of others.

[size=20]scenario[/size]

START — TimerCatchingEvent (PT10S Intermediate Event) (This could be any async script (or) service task) — ScriptTask (or) Service Task (Long running - runs for more than 5 min) — END

[size=20]Issue[/size]

Activiti considers any tasks running for more than 5 min as long running tasks and thinks that the task is stuck and rerun from the point where the new thread is created (i believe as jbarrez said the job executor does this) in the workflow. It would be nice if this 5 min limit is captured in the user guide.

Even marking the long running task (script (or) service) as 'async' doesn't help.

Activiti team, I request you to capture this behavior either in the user guide or FAQ, please. This would definitely save lot of man hours.

[size=20]Solution[/size]
Make your delegate as a receive task - extend from ReceiveTaskActivityBehavior

eg: public class MyReceiveTask extends ReceiveTaskActivityBehavior

Signal it using runtimeService once the task is done. Assuming your service task id is 'servicetask1' you could signal the task using runtimeService.signal("servicetask1")

Found a relevant thread that explains job executor timeout:
http://forums.activiti.org/content/modelling-async-user-wait-long-running-service-task

topic Re: Timer fired every 5 minutes while executing a long running command in Alfresco Archive

Timer fired every 5 minutes while executing a long running command

Re: Timer fired every 5 minutes while executing a long running command

Re: Timer fired every 5 minutes while executing a long running command

Re: Timer fired every 5 minutes while executing a long running command

Re: Timer fired every 5 minutes while executing a long running command

Re: Timer fired every 5 minutes while executing a long running command