Job-Executor executes Activity twice (flowable 5)

Flowable Engine
1

Hi Flowable Team,

we are still on Flowable 5.23. When having heavy load in production, we see from time to time, that a Service-Task (lets say my-activity-1) is executed twice.

We see that because our Log-Files prints out

2019-12-05 15:18:54,067 | INFO | pool-34-thread-1 | LoggingOutInterceptor | 343818 | my-activity-1 |
…
2019-12-05 15:18:54,173 | INFO | pool-34-thread-2 | LoggingOutInterceptor | 343818 | my-activity-1 |

So two threads execute the same Job for Process-Instance (343818) at the same time.

Any idea, how to resolve this issue?

2

Perhaps this behaviour sounds too strange and that’s why I receive no feedback, here some more details:

For a ReceiveTask, a JobEntity was added

2019-12-06 13:26:27,341 | DEBUG | pool-60-thread-3 | DbSqlSession                     |  |  | 311 - org.activiti.engine - 5.23.0 |   insert JobEntity [id=453544]
2019-12-06 13:26:27,341 | DEBUG | pool-60-thread-3 | DbSqlSession                     |  |  | 311 - org.activiti.engine - 5.23.0 |   update ProcessInstance[453328]
2019-12-06 13:26:27,354 | DEBUG | pool-60-thread-6 | LockExclusiveJobCmd              |  |  | 311 - org.activiti.engine - 5.23.0 | Executing lock exclusive job 453544 453328
2019-12-06 13:26:27,357 | DEBUG | pool-60-thread-6 | unacquireJob                     |  |  | 320 - org.mybatis.mybatis - 3.4.1 | ==> Parameters: 2019-12-06 13:26:27.357(Timestamp), 453544(String)

The workflow gets signalled and reaches another ReceiveTask with a new JobEntity. But the former JobEntity is still in the Database and gets executed exactly 10 Seconds later - after another JobEntity

2019-12-06 13:26:32,557 | DEBUG | pool-60-thread-8 | DbSqlSession                     |  |  | 311 - org.activiti.engine - 5.23.0 |   insert JobEntity [id=453555]
2019-12-06 13:26:32,557 | DEBUG | pool-60-thread-8 | DbSqlSession                     |  |  | 311 - org.activiti.engine - 5.23.0 |   update ProcessInstance[453328]

had already executed the StartListener of the ReceiveTask, so the StartListener is executed twice.

2019-12-06 13:26:37,273 | DEBUG | Thread-81        | LogInterceptor                   |  |  | 311 - org.activiti.engine - 5.23.0 | --- starting AcquireAsyncJobsDueCmd --------------------------------------
2019-12-06 13:26:37,279 | DEBUG | Thread-81        | DbSqlSession                     |  |  | 311 - org.activiti.engine - 5.23.0 |   update JobEntity [id=453544]
2019-12-06 13:26:37,286 | DEBUG | pool-60-thread-2 | LockExclusiveJobCmd              |  |  | 311 - org.activiti.engine - 5.23.0 | Executing lock exclusive job 453544 453328

Any ideas, why the job gets executed after 10 seconds?

3

Reducing the defaultAsyncJobAcquireWaitTimeInMillis setting helps in this case.

Does anyboy have an explanation for this behaviour?

4

Hard to say without more information about the process model. Is the service task async? If so, seeing it twice might mean you have an optimistic lock later on in the flow, and one of the two has been rolled back (but the logging has already happened).

That setting changes the polling time of looking for new jobs.

Can you share (a snippet) of your process model here? Also, have you tried using the latest version - many changes have gone in the async executor since.

5

yes, all service and receive tasks are async

After observing the behaviour with our productive bpmn, we could also reproduce it with a simple demo bpmn, having 2 service tasks and 1 receive task. The start listener of the receive task was called twice

no, we are still on 5.23, we will upgrade (hopefully) soon

6

Is is possible to share this simple example? That would clarify a lot.