I use the mariadb docker image 10.3.11 in docker-for-windows, double-checked with a local mariadb installation, no Galera cluster.
BTW I am on Camunda 7.10 with camunda-bpm-spring-boot-starter-webapp and camunda-bpm-spring-boot-starter-rest. With logging enabled like below:
logging:
level:
org.camunda.bpm.engine: DEBUG
I see that the job acquisition thread wakes up regularly and executes the AcquireJobsCmd. The difference seems to be that the h2 version finds a job after the process was started whereas the mariadb version doesn’t:
Successful process creation with h2, AcquireJobsCmd retrieves 1 job at 2019-01-02 15:14:39.758
and then continues with the command ExecuteJobsCmd
:
2019-01-02 15:14:39.750 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14012 Job acquisition thread woke up
2019-01-02 15:14:39.750 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:14:39.750 DEBUG 5680 --- [0.1-8095-exec-9] org.camunda.bpm.engine.cmd : ENGINE-13006 Finishing command -------------------- SubmitStartFormCmd ----------------------
2019-01-02 15:14:39.751 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13009 opening new command context
2019-01-02 15:14:39.751 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Preparing: select RES.* from ACT_RU_JOB RES where (RES.RETRIES_ > 0) and (RES.DUEDATE_ is null or RES.DUEDATE_ <= ?) and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ < ?) and RES.SUSPENSION_STATE_ = 1 and ( ( RES.EXCLUSIVE_ = 1 and not exists( select J2.* from ACT_RU_JOB J2 where J2.PROCESS_INSTANCE_ID_ = RES.PROCESS_INSTANCE_ID_ -- from the same proc. inst. and (J2.EXCLUSIVE_ = 1) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = 0 ) LIMIT ? OFFSET ?
2019-01-02 15:14:39.752 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Parameters: 2019-01-02 15:14:39.751(Timestamp), 2019-01-02 15:14:39.751(Timestamp), 2019-01-02 15:14:39.751(Timestamp), 3(Integer), 0(Integer)
2019-01-02 15:14:39.753 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : <== Total: 1
2019-01-02 15:14:39.753 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13011 closing existing command context
2019-01-02 15:14:39.753 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03006 Cache state after flush: [
PERSISTENT MessageEntity[be04959a-0e98-11e9-ad63-0a158aa072e6]
]
2019-01-02 15:14:39.753 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03008 Flush Summary: [
UPDATE MessageEntity[be04959a-0e98-11e9-ad63-0a158aa072e6]
]
2019-01-02 15:14:39.754 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03009 SQL operation: 'UPDATE'; Entity: 'MessageEntity[id=be04959a-0e98-11e9-ad63-0a158aa072e6]'
2019-01-02 15:14:39.754 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.JobEntity.updateMessage : ==> Preparing: update ACT_RU_JOB SET REV_ = ?, EXECUTION_ID_ = ?, LOCK_EXP_TIME_ = ?, LOCK_OWNER_ = ?, RETRIES_ = ?, EXCEPTION_STACK_ID_ = ?, EXCEPTION_MSG_ = ?, DUEDATE_ = ?, SUSPENSION_STATE_ = ?, PROCESS_DEF_ID_ = ?, PROCESS_DEF_KEY_ = ?, JOB_DEF_ID_ = ?, DEPLOYMENT_ID_ = ?, HANDLER_CFG_ = ?, PRIORITY_ = ?, SEQUENCE_COUNTER_ = ? where ID_= ? and REV_ = ?
2019-01-02 15:14:39.756 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.JobEntity.updateMessage : ==> Parameters: 2(Integer), be046e88-0e98-11e9-ad63-0a158aa072e6(String), 2019-01-02 15:19:39.753(Timestamp), 5687a90d-1060-4f45-a9ad-d14ffe39efa2(String), 3(Integer), null, null, null, 1(Integer), formatPolicy:1:a15d7d86-0e97-11e9-ad63-0a158aa072e6(String), formatPolicy(String), a15d7d87-0e97-11e9-ad63-0a158aa072e6(String), a123339f-0e97-11e9-ad63-0a158aa072e6(String), process-start(String), 0(Long), 1(Long), be04959a-0e98-11e9-ad63-0a158aa072e6(String), 1(Integer)
2019-01-02 15:14:39.757 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03082 Batch summary:
Result 0: update ACT_RU_JOB SET REV_ = ?, EXECUTION_ID_ = ?, LOCK_EXP_TIME_ = ?, LOCK_OWNER_ = ?, RETRIES_ = ?, EXCEPTION_STACK_ID_ = ?, EXCEPTION_MSG_ = ?, DUEDATE_ = ?, SUSPENSION_STATE_ = ?, PROCESS_DEF_ID_ = ?, PROCESS_DEF_KEY_ = ?, JOB_DEF_ID_ = ?, DEPLOYMENT_ID_ = ?, HANDLER_CFG_ = ?, PRIORITY_ = ?, SEQUENCE_COUNTER_ = ? where ID_= ? and REV_ = ? Update counts: [1]
2019-01-02 15:14:39.758 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:14:39.758 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14022 Acquired 1 jobs for process engine 'default': [[be04959a-0e98-11e9-ad63-0a158aa072e6]]
2019-01-02 15:14:39.758 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14023 Execute jobs for process engine 'default': [be04959a-0e98-11e9-ad63-0a158aa072e6]
2019-01-02 15:14:39.758 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:14:39.758 DEBUG 5680 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13009 opening new command context
2019-01-02 15:14:39.759 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Preparing: select RES.* from ACT_RU_JOB RES where (RES.RETRIES_ > 0) and (RES.DUEDATE_ is null or RES.DUEDATE_ <= ?) and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ < ?) and RES.SUSPENSION_STATE_ = 1 and ( ( RES.EXCLUSIVE_ = 1 and not exists( select J2.* from ACT_RU_JOB J2 where J2.PROCESS_INSTANCE_ID_ = RES.PROCESS_INSTANCE_ID_ -- from the same proc. inst. and (J2.EXCLUSIVE_ = 1) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = 0 ) LIMIT ? OFFSET ?
2019-01-02 15:14:39.759 DEBUG 5680 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Parameters: 2019-01-02 15:14:39.758(Timestamp), 2019-01-02 15:14:39.758(Timestamp), 2019-01-02 15:14:39.758(Timestamp), 3(Integer), 0(Integer)
2019-01-02 15:14:39.759 DEBUG 5680 --- [aTaskExecutor-3] org.camunda.bpm.engine.cmd : ENGINE-13005 Starting command -------------------- ExecuteJobsCmd ----------------------
The version with mariadb however receives Update counts: [-2] and then finds 0 Jobs at 2019-01-02 15:16:41.374
; finally, the job acquisition thread goes to sleep. The ExecuteJobsCmd is never executed:
2019-01-02 15:16:41.289 DEBUG 6724 --- [0.1-8095-exec-2] o.c.b.e.i.p.e.JobEntity.insertMessage : ==> Preparing: insert into ACT_RU_JOB ( ID_, TYPE_, LOCK_OWNER_, LOCK_EXP_TIME_, EXCLUSIVE_, EXECUTION_ID_, PROCESS_INSTANCE_ID_, PROCESS_DEF_ID_, PROCESS_DEF_KEY_, RETRIES_, EXCEPTION_STACK_ID_, EXCEPTION_MSG_, DUEDATE_, HANDLER_TYPE_, HANDLER_CFG_, DEPLOYMENT_ID_, SUSPENSION_STATE_, JOB_DEF_ID_, PRIORITY_, SEQUENCE_COUNTER_, TENANT_ID_, CREATE_TIME_, REV_ ) values (?, 'message', ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 )
2019-01-02 15:16:41.289 DEBUG 6724 --- [0.1-8095-exec-2] o.c.b.e.i.p.e.JobEntity.insertMessage : ==> Parameters: 0677cbdb-0e99-11e9-b0ec-0a158aa072e6(String), null, null, true(Boolean), 0674e5a9-0e99-11e9-b0ec-0a158aa072e6(String), 0674e5a9-0e99-11e9-b0ec-0a158aa072e6(String), formatPolicy:4:e725e5ea-0e94-11e9-8dbd-0a158aa072e6(String), formatPolicy(String), 3(Integer), null, null, null, async-continuation(String), process-start(String), e6f49cb3-0e94-11e9-8dbd-0a158aa072e6(String), 1(Integer), e725e5eb-0e94-11e9-8dbd-0a158aa072e6(String), 0(Long), 1(Long), null, 2019-01-02 15:16:41.281(Timestamp)
2019-01-02 15:16:41.327 DEBUG 6724 --- [0.1-8095-exec-2] org.camunda.bpm.engine.persistence : ENGINE-03082 Batch summary:
Result 0: insert into ACT_HI_PROCINST ( ID_, PROC_INST_ID_, BUSINESS_KEY_, PROC_DEF_KEY_, PROC_DEF_ID_, START_TIME_, END_TIME_, REMOVAL_TIME_, DURATION_, START_USER_ID_, START_ACT_ID_, END_ACT_ID_, SUPER_PROCESS_INSTANCE_ID_, ROOT_PROC_INST_ID_, SUPER_CASE_INSTANCE_ID_, CASE_INST_ID_, DELETE_REASON_, TENANT_ID_, STATE_ ) values ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ? ) Update counts: [-2]
Result 1: insert into ACT_RU_EXECUTION ( ID_, ROOT_PROC_INST_ID_, PROC_INST_ID_, BUSINESS_KEY_, PROC_DEF_ID_, ACT_ID_, ACT_INST_ID_, IS_ACTIVE_, IS_CONCURRENT_, IS_SCOPE_, IS_EVENT_SCOPE_, PARENT_ID_, SUPER_EXEC_, SUPER_CASE_EXEC_, CASE_INST_ID_, SUSPENSION_STATE_, CACHED_ENT_STATE_, SEQUENCE_COUNTER_, TENANT_ID_, REV_ ) values ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 ) Update counts: [-2]
Result 2: insert into ACT_RU_VARIABLE ( ID_, TYPE_, NAME_, PROC_INST_ID_, EXECUTION_ID_, CASE_INST_ID_, CASE_EXECUTION_ID_, TASK_ID_, BYTEARRAY_ID_, DOUBLE_, LONG_, TEXT_, TEXT2_, VAR_SCOPE_, SEQUENCE_COUNTER_, IS_CONCURRENT_LOCAL_, TENANT_ID_, REV_ ) values ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 ) Update counts: [-2]
Result 3: insert into ACT_RU_JOB ( ID_, TYPE_, LOCK_OWNER_, LOCK_EXP_TIME_, EXCLUSIVE_, EXECUTION_ID_, PROCESS_INSTANCE_ID_, PROCESS_DEF_ID_, PROCESS_DEF_KEY_, RETRIES_, EXCEPTION_STACK_ID_, EXCEPTION_MSG_, DUEDATE_, HANDLER_TYPE_, HANDLER_CFG_, DEPLOYMENT_ID_, SUSPENSION_STATE_, JOB_DEF_ID_, PRIORITY_, SEQUENCE_COUNTER_, TENANT_ID_, CREATE_TIME_, REV_ ) values (?, 'message', ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, 1 ) Update counts: [-2]
...
2019-01-02 15:16:41.335 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14012 Job acquisition thread woke up
2019-01-02 15:16:41.335 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:16:41.337 DEBUG 6724 --- [0.1-8095-exec-2] org.camunda.bpm.engine.cmd : ENGINE-13006 Finishing command -------------------- SubmitStartFormCmd ----------------------
2019-01-02 15:16:41.340 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13009 opening new command context
2019-01-02 15:16:41.340 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Preparing: select RES.* from ACT_RU_JOB RES where (RES.RETRIES_ > 0) and (RES.DUEDATE_ is null or RES.DUEDATE_ <= ?) and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ < ?) and RES.SUSPENSION_STATE_ = 1 and ( ( RES.EXCLUSIVE_ = 1 and not exists( select J2.* from ACT_RU_JOB J2 where J2.PROCESS_INSTANCE_ID_ = RES.PROCESS_INSTANCE_ID_ -- from the same proc. inst. and (J2.EXCLUSIVE_ = 1) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = 0 ) LIMIT ? OFFSET ?
2019-01-02 15:16:41.341 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Parameters: 2019-01-02 15:16:41.34(Timestamp), 2019-01-02 15:16:41.34(Timestamp), 2019-01-02 15:16:41.34(Timestamp), 3(Integer), 0(Integer)
2019-01-02 15:16:41.348 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : <== Total: 1
2019-01-02 15:16:41.348 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13011 closing existing command context
2019-01-02 15:16:41.348 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03006 Cache state after flush: [
PERSISTENT MessageEntity[0677cbdb-0e99-11e9-b0ec-0a158aa072e6]
]
2019-01-02 15:16:41.348 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03008 Flush Summary: [
UPDATE MessageEntity[0677cbdb-0e99-11e9-b0ec-0a158aa072e6]
]
2019-01-02 15:16:41.348 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03009 SQL operation: 'UPDATE'; Entity: 'MessageEntity[id=0677cbdb-0e99-11e9-b0ec-0a158aa072e6]'
2019-01-02 15:16:41.349 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.JobEntity.updateMessage : ==> Preparing: update ACT_RU_JOB SET REV_ = ?, EXECUTION_ID_ = ?, LOCK_EXP_TIME_ = ?, LOCK_OWNER_ = ?, RETRIES_ = ?, EXCEPTION_STACK_ID_ = ?, EXCEPTION_MSG_ = ?, DUEDATE_ = ?, SUSPENSION_STATE_ = ?, PROCESS_DEF_ID_ = ?, PROCESS_DEF_KEY_ = ?, JOB_DEF_ID_ = ?, DEPLOYMENT_ID_ = ?, HANDLER_CFG_ = ?, PRIORITY_ = ?, SEQUENCE_COUNTER_ = ? where ID_= ? and REV_ = ?
2019-01-02 15:16:41.349 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.JobEntity.updateMessage : ==> Parameters: 2(Integer), 0674e5a9-0e99-11e9-b0ec-0a158aa072e6(String), 2019-01-02 15:21:41.348(Timestamp), cc0a239e-2e3c-4eab-b5d3-e9cad48eb8c5(String), 3(Integer), null, null, null, 1(Integer), formatPolicy:4:e725e5ea-0e94-11e9-8dbd-0a158aa072e6(String), formatPolicy(String), e725e5eb-0e94-11e9-8dbd-0a158aa072e6(String), e6f49cb3-0e94-11e9-8dbd-0a158aa072e6(String), process-start(String), 0(Long), 1(Long), 0677cbdb-0e99-11e9-b0ec-0a158aa072e6(String), 1(Integer)
2019-01-02 15:16:41.355 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03082 Batch summary:
Result 0: update ACT_RU_JOB SET REV_ = ?, EXECUTION_ID_ = ?, LOCK_EXP_TIME_ = ?, LOCK_OWNER_ = ?, RETRIES_ = ?, EXCEPTION_STACK_ID_ = ?, EXCEPTION_MSG_ = ?, DUEDATE_ = ?, SUSPENSION_STATE_ = ?, PROCESS_DEF_ID_ = ?, PROCESS_DEF_KEY_ = ?, JOB_DEF_ID_ = ?, DEPLOYMENT_ID_ = ?, HANDLER_CFG_ = ?, PRIORITY_ = ?, SEQUENCE_COUNTER_ = ? where ID_= ? and REV_ = ? Update counts: [-2]
2019-01-02 15:16:41.362 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:16:41.362 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14022 Acquired 0 jobs for process engine 'default': []
2019-01-02 15:16:41.363 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:16:41.364 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13009 opening new command context
2019-01-02 15:16:41.365 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Preparing: select RES.* from ACT_RU_JOB RES where (RES.RETRIES_ > 0) and (RES.DUEDATE_ is null or RES.DUEDATE_ <= ?) and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ < ?) and RES.SUSPENSION_STATE_ = 1 and ( ( RES.EXCLUSIVE_ = 1 and not exists( select J2.* from ACT_RU_JOB J2 where J2.PROCESS_INSTANCE_ID_ = RES.PROCESS_INSTANCE_ID_ -- from the same proc. inst. and (J2.EXCLUSIVE_ = 1) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = 0 ) LIMIT ? OFFSET ?
2019-01-02 15:16:41.365 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : ==> Parameters: 2019-01-02 15:16:41.364(Timestamp), 2019-01-02 15:16:41.364(Timestamp), 2019-01-02 15:16:41.364(Timestamp), 3(Integer), 0(Integer)
2019-01-02 15:16:41.369 DEBUG 6724 --- [ingJobExecutor]] o.c.b.e.i.p.e.J.selectNextJobsToExecute : <== Total: 0
2019-01-02 15:16:41.369 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13011 closing existing command context
2019-01-02 15:16:41.369 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.persistence : ENGINE-03006 Cache state after flush: [
]
2019-01-02 15:16:41.374 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.cmd : ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------
2019-01-02 15:16:41.374 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14022 Acquired 0 jobs for process engine 'default': []
2019-01-02 15:16:41.374 DEBUG 6724 --- [ingJobExecutor]] org.camunda.bpm.engine.jobexecutor : ENGINE-14011 Job acquisition thread sleeping for 4989 millis
The query that doesn’t find a job in mariadb is:
select RES.*
from ACT_RU_JOB RES
where (RES.RETRIES_ > 0)
and (RES.DUEDATE_ is null or RES.DUEDATE_ <= ?)
and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ < ?)
and RES.SUSPENSION_STATE_ = 1
and (
(
RES.EXCLUSIVE_ = 1 and not exists
(
select J2.*
from ACT_RU_JOB J2
where J2.PROCESS_INSTANCE_ID_ = RES.PROCESS_INSTANCE_ID_ -- from the same proc. inst.
and (J2.EXCLUSIVE_ = 1) -- also exclusive
and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress
)
)
or RES.EXCLUSIVE_ = 0)
LIMIT ? OFFSET ?;