Async task locking and processing

Hello,

I have some issues caused by what I assume is tasks not being locked long enough when executed in parallel. Stack trace is a s follows:

org.camunda.bpm.client.exception.NotAcquiredException: TASK/CLIENT-01007 Exception while extending lock: The task's most recent lock could not be acquired
	at org.camunda.bpm.client.impl.ExternalTaskClientLogger.externalTaskServiceException(ExternalTaskClientLogger.java:116) ~[camunda-external-task-client-7.16.0.jar:7.16.0]
	at org.camunda.bpm.client.task.impl.ExternalTaskServiceImpl.extendLock(ExternalTaskServiceImpl.java:160) ~[camunda-external-task-client-7.16.0.jar:7.16.0]
	at org.camunda.bpm.client.task.impl.ExternalTaskServiceImpl.extendLock(ExternalTaskServiceImpl.java:152) ~[camunda-external-task-client-7.16.0.jar:7.16.0]
	at io.company.tasks.MyExternalTaskHandler.execute(MyExternalTaskHandler.java:266) ~[classes/:?]
	at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.handleExternalTask(TopicSubscriptionManager.java:152) ~[camunda-external-task-client-7.16.0.jar:7.16.0]
	at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.lambda$acquire$0(TopicSubscriptionManager.java:108) ~[camunda-external-task-client-7.16.0.jar:7.16.0]
	at java.util.Arrays$ArrayList.forEach(Arrays.java:4204) [?:?]
	at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.acquire(TopicSubscriptionManager.java:103) [camunda-external-task-client-7.16.0.jar:7.16.0]
	at org.camunda.bpm.client.topic.impl.TopicSubscriptionManager.run(TopicSubscriptionManager.java:87) [camunda-external-task-client-7.16.0.jar:7.16.0]
	at java.lang.Thread.run(Thread.java:833) [?:?]

I am trying to find which exact task causes this, but I’m having some issues. My main issue is that I would assume tasks are locked per task instance, but from what I’m seeing in logs, that doesn’t seem to be the case.

Let’s say I have process instances A, B, C, D. A and B are instances of process_definition1 and C and D are instances of process_definition2.
If I look at process instance A, I can see that previous service task has completed successfully, and after some time and work on processes B/C/D, worker starts processing next service task for A. It tries to extend lock to a predicted processing time and that’s when I get the exception above.

Is this possible, or am I missing someplace where we’re processing tasks? If it’s possible, how exactly does Camunda lock external tasks? Topic name/task id/something else?

Thank you for your time

Hello @Lovry ,

in order to extend the lock, the task still has to be locked.

Here is a description of the called endpoint:

It might make sense to play a bit with the delay before extending the lock duration.

I hope this helps

Jonathan

Thanks, that makes sense. I’ll try with longer initial lock duration, though it was 10 seconds already.

I do see in current example that the difference is 2 seconds between org.camunda.bpm.client.topic.impl.TopicSubscriptionManager calling execute on my TaskHandler and my code trying to extend lock. I guess it lost more seconds somewhere down the call stack.

I’ll try with slightly longer initial locks. The thing is, I already tried setting them to 45 seconds previously, but then starting multiple process instances like in the example above (A, B, C, D where A and B are instance of process_definition1 and C and D are instances of process_definition2), deadlock exceptions like in the example below when triggering process starts in Camunda seemed a lot more common.

Caused by: org.camunda.bpm.engine.ProcessEngineException: ENGINE-03083 Unexpected exception while executing database operations with message ’

Error flushing statements. Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 62) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
Cause: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 62) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.’.

[

INSERT HistoricVariableInstanceEntity[d5396b00-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableInstanceEntity[d5396b03-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableInstanceEntity[d5396b05-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableInstanceEntity[d5396b07-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableInstanceEntity[d5396b09-9724-11ed-8044-0242ac110002]

INSERT UserOperationLogEntryEventEntity[d53af1ac-9724-11ed-8044-0242ac110002]

INSERT UserOperationLogEntryEventEntity[d5ac9f46-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableUpdateEventEntity[d5396b02-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableUpdateEventEntity[d5396b04-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableUpdateEventEntity[d5396b06-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableUpdateEventEntity[d5396b08-9724-11ed-8044-0242ac110002]

INSERT HistoricVariableUpdateEventEntity[d5396b0a-9724-11ed-8044-0242ac110002]

INSERT HistoricProcessInstanceEventEntity[d53943ef-9724-11ed-8044-0242ac110002]

INSERT HistoricExternalTaskLogEntity[d5ac9f44-9724-11ed-8044-0242ac110002]

INSERT HistoricActivityInstanceEventEntity[Gateway_1xska4n:d53af1ad-9724-11ed-8044-0242ac110002]

INSERT HistoricActivityInstanceEventEntity[MyServiceTask:d5abdbf0-9724-11ed-8044-0242ac110002]

INSERT HistoricActivityInstanceEventEntity[StartEvent_1:d5396b0b-9724-11ed-8044-0242ac110002]

INSERT ExecutionEntity[d53943ef-9724-11ed-8044-0242ac110002]

INSERT ExecutionEntity[d5abdbef-9724-11ed-8044-0242ac110002]

INSERT VariableInstanceEntity[d5396b00-9724-11ed-8044-0242ac110002]

INSERT VariableInstanceEntity[d5396b03-9724-11ed-8044-0242ac110002]

INSERT VariableInstanceEntity[d5396b05-9724-11ed-8044-0242ac110002]

INSERT VariableInstanceEntity[d5396b07-9724-11ed-8044-0242ac110002]

INSERT VariableInstanceEntity[d5396b09-9724-11ed-8044-0242ac110002]

INSERT ExternalTaskEntity[d5ac7832-9724-11ed-8044-0242ac110002]

UPDATE_BULK updateExternalTaskSuspensionStateByParameters org.camunda.bpm.engine.impl.db.ListQueryParameterObject@639acbd

UPDATE_BULK updateJobSuspensionStateByParameters org.camunda.bpm.engine.impl.db.ListQueryParameterObject@575ec3f9

UPDATE_BULK updateTaskSuspensionStateByParameters org.camunda.bpm.engine.impl.db.ListQueryParameterObject@2293c102

UPDATE_BULK updateExecutionSuspensionStateByParameters org.camunda.bpm.engine.impl.db.ListQueryParameterObject@1d9135bf

]

EDIT: Definitely have deadlocks happening more often, several process instances fail to start consistently on each try. Service task that sets a process variable is always in the flush summary (MyServiceTask mentioned above).

Hello @Lovry ,

from your stacktrace I can see that you are using MSSQL. There is a section on how to configure transaction isolation levels in order to function properly with Camunda:

Did you already apply this?

Jonathan

I did not have snapshot isolation enabled on this database, thanks! Everything is solved.