Hyland Connect

nchan · ‎11-14-2014

Activiti version tested : 5.16 and 5.10

I 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) — END

The script task runs for more than 5 minutes. While this happens, the timer is getting fired again and again every 5 min (approx). I don't have time cycle set. Enclosed the BPMN file.

What am i missing here, please?

Note: This is just a sample project i have created for the post. This timer is part of a bigger workflow (sitting inside a sub workflow) and behaves exactly the same way i explained here.


<?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:omgdc="http://www.omg.org/spec/DD/20100524/DC" xmlns:omgdi="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">
      <timerEventDefinition>
        <timeDuration>PT10S</timeDuration>
      </timerEventDefinition>
    </intermediateCatchEvent>
    <sequenceFlow id="flow24" sourceRef="timerintermediatecatchevent3" targetRef="scripttask5"></sequenceFlow>
    <scriptTask id="scripttask5" name="Long running command" scriptFormat="groovy" activiti:autoStoreVariables="false">
      <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">
    </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>
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Here is the unit test that runs this code:


package org.activiti.designer.test;

import static org.junit.Assert.*;
import java.util.Date;
import java.util.HashMap;
import java.util.Map;
import java.util.logging.Logger;
import java.io.FileInputStream;
import org.activiti.engine.RepositoryService;
import org.activiti.engine.RuntimeService;
import org.activiti.engine.runtime.ProcessInstance;
import org.activiti.engine.test.ActivitiRule;
import org.junit.Rule;
import org.junit.Test;


public class ProcessTestMyProcess {

   private Logger LOG = Logger.getLogger(ProcessTestMyProcess.class.getName());
   private String filename = "/Users/nchan/Projects/eclipse-ws/luna-groovy/ezcommit/cca-workflow-mock/src/main/resources/diagrams/mock-workflow.bpmn";
   
   private String PROCESS_MAIN = "myProcess";

   @Rule
   public ActivitiRule activitiRule = new ActivitiRule();

   @Test
   public void startProcess() throws Exception {
      RepositoryService repositoryService = activitiRule.getRepositoryService();
      repositoryService.createDeployment().addInputStream("myProcess.bpmn20.xml",
            new FileInputStream(filename)).deploy();
      RuntimeService runtimeService = activitiRule.getRuntimeService();
      
      Map<String, Object> variableMap = new HashMap<String, Object>();
      variableMap.put("name", "Activiti");
      ProcessInstance processInstance = runtimeService.startProcessInstanceByKey("myProcess", variableMap);
      
      int waitCnt = 0;
      LOG.info("Thread:" + Thread.currentThread().getId() + " – Started process instance @" + new Date());
   
      while (isWorkflowActive(runtimeService)) {
            LOG.info("workflow running …" + ++waitCnt + "@" + new Date());
            //wait for specified duration and check again
            Thread.sleep(10000);
        }
       
      LOG.info("Thread:" + Thread.currentThread().getId() + " – Ended process instance @" + new Date());
      assertNotNull(processInstance.getId());
      System.out.println("id " + processInstance.getId() + " "
            + processInstance.getProcessDefinitionId());
   }
   
   private final boolean isWorkflowActive(RuntimeService runtimeService) {
      ProcessInstance pi = runtimeService.createProcessInstanceQuery()
            .processDefinitionKey(PROCESS_MAIN)
            .singleResult();
      if (pi != null) {
         return !pi.isEnded();
      } else {
         return false;
      }
   }
}
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Here is my activiti.cfg.xml file:


<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
   xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
   xmlns:context="http://www.springframework.org/schema/context"
   xsi:schemaLocation="http://www.springframework.org/schema/beans
            http://www.springframework.org/schema/beans/spring-beans.xsd 
            http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context.xsd">
    
   <bean id="processEngineConfiguration"
      class="org.activiti.engine.impl.cfg.StandaloneInMemProcessEngineConfiguration">
      <property name="databaseSchemaUpdate" value="true" />
      <property name="jobExecutorActivate" value="true" />
   </bean>

   <bean id="processEngine" class="org.activiti.spring.ProcessEngineFactoryBean">
      <property name="processEngineConfiguration" ref="processEngineConfiguration" />
   </bean>
   
   <bean id="runtimeService" factory-bean="processEngine"
      factory-method="getRuntimeService" />

</beans>
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

trademak · ‎11-14-2014

Could you retest when you make the script task async?

Best regards,

nchan · ‎11-14-2014

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" xmlnsmgdc="http://www.omg.org/spec/DD/20100524/DC" xmlnsmgdi="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 ..

jbarrez · ‎11-19-2014

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.

jbarrez · ‎11-20-2014

>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.

nchan · ‎11-20-2014

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

Hyland Connect

Timer fired every 5 minutes while executing a long running command