Logging level is at DEBUG without having changed it

jilleJr · November 22, 2019, 12:04pm

Having an issue where our CI deployed Camunda BPM platform has for unknown reason switched to DEBUG logging level on a lot of items. And we do not know why.

My setup

based on camunda/camunda-bpm-platform:tomcat-7.11.0 (https://github.com/camunda/docker-camunda-bpm-platform) docker image
- with removed /camunda/webapps/camunda-invoice webapp
using PostgreSQL as database
having two plugins added
- one for some RabbitMQ reporting and
- one for double types in generated forms. Nothing too special.
using the LDAP plugin as identity provider

The logs

Running locally I get normal behavior with only INFO logs, but when running on the k8s node it reports DEBUG logs which smog up the logs a lot.
I’m getting logs like these:

10:13:01.731 [http-nio-8080-exec-10] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committing...
2019-11-22 11:13:01	10:13:01.731 [http-nio-8080-exec-10] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 committing the persistence session...
2019-11-22 11:13:01	10:13:01.731 [http-nio-8080-exec-10] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committed...
2019-11-22 11:13:01	10:13:01.731 [http-nio-8080-exec-10] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:01	10:13:01.732 [http-nio-8080-exec-10] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:01	10:13:01.732 [http-nio-8080-exec-10] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13006 Finishing command -------------------- GetRenderedTaskFormCmd ----------------------
2019-11-22 11:13:01	10:13:01.753 [http-nio-8080-exec-7] DEBUG o.j.r.core.SynchronousDispatcher - PathInfo: /engine/default/task/a1b087bf-0d10-11ea-b0fe-0692f0e4befb/form-variables
2019-11-22 11:13:01	10:13:01.754 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13005 Starting command -------------------- GetTaskFormVariablesCmd ----------------------
2019-11-22 11:13:01	10:13:01.754 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13009 opening new command context
2019-11-22 11:13:01	10:13:01.755 [http-nio-8080-exec-7] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
2019-11-22 11:13:01	10:13:01.755 [http-nio-8080-exec-7] DEBUG o.a.i.t.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:01	10:13:01.755 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.TaskEntity.selectTask - ==> Preparing: select * from ACT_RU_TASK where ID_ = ?
2019-11-22 11:13:01	10:13:01.755 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.TaskEntity.selectTask - ==> Parameters: a1b087bf-0d10-11ea-b0fe-0692f0e4befb(String)
2019-11-22 11:13:01	10:13:01.756 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.TaskEntity.selectTask - <== Total: 1
2019-11-22 11:13:01	10:13:01.756 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.E.selectExecution - ==> Preparing: select * from ACT_RU_EXECUTION where ID_ = ?
2019-11-22 11:13:01	10:13:01.756 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.E.selectExecution - ==> Parameters: a1b0128b-0d10-11ea-b0fe-0692f0e4befb(String)
2019-11-22 11:13:01	10:13:01.757 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.E.selectExecution - <== Total: 1
2019-11-22 11:13:01	10:13:01.757 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.P.selectProcessDefinition - ==> Preparing: select * from ACT_RE_PROCDEF where ID_ = ?
2019-11-22 11:13:01	10:13:01.757 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.P.selectProcessDefinition - ==> Parameters: DemoFoodProcess:2:985fe2ef-0d10-11ea-b0fe-0692f0e4befb(String)
2019-11-22 11:13:01	10:13:01.758 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.P.selectProcessDefinition - <== Total: 1
2019-11-22 11:13:01	10:13:01.758 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.selectAuthorizedGroupIds - ==> Preparing: SELECT distinct(A.GROUP_ID_) FROM ACT_RU_AUTHORIZATION A
2019-11-22 11:13:01	10:13:01.758 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.selectAuthorizedGroupIds - ==> Parameters:
2019-11-22 11:13:01	10:13:01.759 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.selectAuthorizedGroupIds - <== Total: 2
2019-11-22 11:13:01	10:13:01.759 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.selectRevokeAuthorization - ==> Preparing: SELECT CASE WHEN EXISTS ( SELECT ID_ FROM ACT_RU_AUTHORIZATION WHERE TYPE_ = 2 AND ( USER_ID_ IN (?, '*') ) ) THEN 1 ELSE 0 END
2019-11-22 11:13:01	10:13:01.759 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.selectRevokeAuthorization - ==> Parameters: kalle.jillheden(String)
2019-11-22 11:13:01	10:13:01.759 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.selectRevokeAuthorization - <== Total: 1
2019-11-22 11:13:01	10:13:01.760 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.isUserAuthorizedForResource - ==> Preparing: SELECT COALESCE(( SELECT CASE WHEN EXISTS (SELECT A.RESOURCE_ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 1 AND A.USER_ID_ = ? AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = ? ) THEN 1 WHEN EXISTS (SELECT ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 1 AND A.USER_ID_ = ? AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = '*') THEN 1 ELSE ( SELECT CASE WHEN EXISTS (SELECT A.RESOURCE_ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 0 AND A.USER_ID_ = '*' AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = ? ) THEN 1 WHEN EXISTS (SELECT ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 0 AND A.USER_ID_ = '*' AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = '*') THEN 1 ELSE null END ) END ) , COALESCE(( SELECT CASE WHEN EXISTS (SELECT A.RESOURCE_ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 1 AND A.USER_ID_ = ? AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = ? ) THEN 1 WHEN EXISTS (SELECT ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 1 AND A.USER_ID_ = ? AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = '*') THEN 1 ELSE ( SELECT CASE WHEN EXISTS (SELECT A.RESOURCE_ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 0 AND A.USER_ID_ = '*' AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = ? ) THEN 1 WHEN EXISTS (SELECT ID_ FROM ACT_RU_AUTHORIZATION A WHERE A.TYPE_ = 0 AND A.USER_ID_ = '*' AND A.PERMS_ & ? = ? AND A.RESOURCE_TYPE_ = ? AND A.RESOURCE_ID_ = '*') THEN 1 ELSE null END ) END ) , 0 ) )
2019-11-22 11:13:01	10:13:01.760 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.isUserAuthorizedForResource - ==> Parameters: kalle.jillheden(String), 2(Integer), 2(Integer), 7(Integer), a1b087bf-0d10-11ea-b0fe-0692f0e4befb(String), kalle.jillheden(String), 2(Integer), 2(Integer), 7(Integer), 2(Integer), 2(Integer), 7(Integer), a1b087bf-0d10-11ea-b0fe-0692f0e4befb(String), 2(Integer), 2(Integer), 7(Integer), kalle.jillheden(String), 64(Integer), 64(Integer), 6(Integer), DemoFoodProcess(String), kalle.jillheden(String), 64(Integer), 64(Integer), 6(Integer), 64(Integer), 64(Integer), 6(Integer), DemoFoodProcess(String), 64(Integer), 64(Integer), 6(Integer)
2019-11-22 11:13:01	10:13:01.762 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.A.isUserAuthorizedForResource - <== Total: 1
2019-11-22 11:13:01	10:13:01.762 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByExecutionId - ==> Preparing: SELECT RES.*, ( case when RES.TASK_ID_ is not null and RES.EXECUTION_ID_ is not null then EXECUTION.ACT_INST_ID_ when RES.CASE_EXECUTION_ID_ is not null then RES.CASE_EXECUTION_ID_ when EXECUTION.PARENT_ID_ is null and RES.IS_CONCURRENT_LOCAL_ = false then EXECUTION.ID_ when EXECUTION.IS_SCOPE_ = true and EXECUTION.PARENT_ID_ is not null and RES.IS_CONCURRENT_LOCAL_ = false then PARENT_EXECUTION.ACT_INST_ID_ else EXECUTION.ACT_INST_ID_ end ) ACT_INST_ID_ FROM ACT_RU_VARIABLE RES LEFT JOIN ACT_RU_EXECUTION EXECUTION ON RES.EXECUTION_ID_ = EXECUTION.ID_ LEFT JOIN ACT_RU_EXECUTION PARENT_EXECUTION ON EXECUTION.PARENT_ID_ = PARENT_EXECUTION.ID_ WHERE EXECUTION_ID_ = ? AND TASK_ID_ is null
2019-11-22 11:13:01	10:13:01.762 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByExecutionId - ==> Parameters: a1b0128b-0d10-11ea-b0fe-0692f0e4befb(String)
2019-11-22 11:13:01	10:13:01.763 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByExecutionId - <== Total: 1
2019-11-22 11:13:01	10:13:01.763 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.E.selectExecutionsByProcessInstanceId - ==> Preparing: select * from ACT_RU_EXECUTION where PROC_INST_ID_ = ?
2019-11-22 11:13:01	10:13:01.763 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.E.selectExecutionsByProcessInstanceId - ==> Parameters: a1afeb70-0d10-11ea-b0fe-0692f0e4befb(String)
2019-11-22 11:13:01	10:13:01.764 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.E.selectExecutionsByProcessInstanceId - <== Total: 2
2019-11-22 11:13:01	10:13:01.764 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByExecutionId - ==> Preparing: SELECT RES.*, ( case when RES.TASK_ID_ is not null and RES.EXECUTION_ID_ is not null then EXECUTION.ACT_INST_ID_ when RES.CASE_EXECUTION_ID_ is not null then RES.CASE_EXECUTION_ID_ when EXECUTION.PARENT_ID_ is null and RES.IS_CONCURRENT_LOCAL_ = false then EXECUTION.ID_ when EXECUTION.IS_SCOPE_ = true and EXECUTION.PARENT_ID_ is not null and RES.IS_CONCURRENT_LOCAL_ = false then PARENT_EXECUTION.ACT_INST_ID_ else EXECUTION.ACT_INST_ID_ end ) ACT_INST_ID_ FROM ACT_RU_VARIABLE RES LEFT JOIN ACT_RU_EXECUTION EXECUTION ON RES.EXECUTION_ID_ = EXECUTION.ID_ LEFT JOIN ACT_RU_EXECUTION PARENT_EXECUTION ON EXECUTION.PARENT_ID_ = PARENT_EXECUTION.ID_ WHERE EXECUTION_ID_ = ? AND TASK_ID_ is null
2019-11-22 11:13:01	10:13:01.764 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByExecutionId - ==> Parameters: a1afeb70-0d10-11ea-b0fe-0692f0e4befb(String)
2019-11-22 11:13:01	10:13:01.765 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByExecutionId - <== Total: 3
2019-11-22 11:13:01	10:13:01.766 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByTaskId - ==> Preparing: SELECT RES.*, ( case when RES.TASK_ID_ is not null and RES.EXECUTION_ID_ is not null then EXECUTION.ACT_INST_ID_ when RES.CASE_EXECUTION_ID_ is not null then RES.CASE_EXECUTION_ID_ when EXECUTION.PARENT_ID_ is null and RES.IS_CONCURRENT_LOCAL_ = false then EXECUTION.ID_ when EXECUTION.IS_SCOPE_ = true and EXECUTION.PARENT_ID_ is not null and RES.IS_CONCURRENT_LOCAL_ = false then PARENT_EXECUTION.ACT_INST_ID_ else EXECUTION.ACT_INST_ID_ end ) ACT_INST_ID_ FROM ACT_RU_VARIABLE RES LEFT JOIN ACT_RU_EXECUTION EXECUTION ON RES.EXECUTION_ID_ = EXECUTION.ID_ LEFT JOIN ACT_RU_EXECUTION PARENT_EXECUTION ON EXECUTION.PARENT_ID_ = PARENT_EXECUTION.ID_ WHERE TASK_ID_ = ? AND NAME_ IN ( ? , ? , ? )
2019-11-22 11:13:01	10:13:01.766 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByTaskId - ==> Parameters: a1b087bf-0d10-11ea-b0fe-0692f0e4befb(String), food_item(String), quantity(String), approved(String)
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG o.c.b.e.i.p.e.V.selectVariablesByTaskId - <== Total: 0
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13011 closing existing command context
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.persistence - ENGINE-03006 Cache state after flush: [
2019-11-22 11:13:01	PERSISTENT ProcessDefinitionEntity[DemoFoodProcess:2:985fe2ef-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT VariableInstanceEntity[a1afeb71-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT VariableInstanceEntity[a1b060ad-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT VariableInstanceEntity[a1afeb74-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT VariableInstanceEntity[a1afeb73-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT ExecutionEntity[a1afeb70-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT ExecutionEntity[a1b0128b-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	PERSISTENT TaskEntity[a1b087bf-0d10-11ea-b0fe-0692f0e4befb]
2019-11-22 11:13:01	]
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committing...
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 committing the persistence session...
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committed...
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:01	10:13:01.767 [http-nio-8080-exec-7] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13006 Finishing command -------------------- GetTaskFormVariablesCmd ----------------------
2019-11-22 11:13:33	10:13:33.445 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14012 Job acquisition thread woke up
2019-11-22 11:13:33	10:13:33.445 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-11-22 11:13:33	10:13:33.445 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13009 opening new command context
2019-11-22 11:13:33	10:13:33.446 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
2019-11-22 11:13:33	10:13:33.447 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:33	10:13:33.447 [Thread-6] DEBUG 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.DEPLOYMENT_ID_ is null or ( RES.DEPLOYMENT_ID_ IN ( ? ) ) ) and ( ( RES.EXCLUSIVE_ = true 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_ = true) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = false ) LIMIT ? OFFSET ?
2019-11-22 11:13:33	10:13:33.447 [Thread-6] DEBUG o.c.b.e.i.p.e.J.selectNextJobsToExecute - ==> Parameters: 2019-11-22 10:13:33.445(Timestamp), 2019-11-22 10:13:33.445(Timestamp), 9845a42d-0d10-11ea-b0fe-0692f0e4befb(String), 2019-11-22 10:13:33.445(Timestamp), 3(Integer), 0(Integer)
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG o.c.b.e.i.p.e.J.selectNextJobsToExecute - <== Total: 0
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13011 closing existing command context
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.persistence - ENGINE-03006 Cache state after flush: [
2019-11-22 11:13:33	]
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committing...
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 committing the persistence session...
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committed...
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14022 Acquired 0 jobs for process engine 'default': []
2019-11-22 11:13:33	10:13:33.458 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14011 Job acquisition thread sleeping for 59987 millis
2019-11-22 11:14:33	10:14:33.446 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14012 Job acquisition thread woke up
2019-11-22 11:14:33	10:14:33.446 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-11-22 11:14:33	10:14:33.446 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13009 opening new command context
2019-11-22 11:14:33	10:14:33.446 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
2019-11-22 11:14:33	10:14:33.447 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:14:33	10:14:33.447 [Thread-6] DEBUG 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.DEPLOYMENT_ID_ is null or ( RES.DEPLOYMENT_ID_ IN ( ? ) ) ) and ( ( RES.EXCLUSIVE_ = true 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_ = true) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = false ) LIMIT ? OFFSET ?
2019-11-22 11:14:33	10:14:33.447 [Thread-6] DEBUG o.c.b.e.i.p.e.J.selectNextJobsToExecute - ==> Parameters: 2019-11-22 10:14:33.446(Timestamp), 2019-11-22 10:14:33.446(Timestamp), 9845a42d-0d10-11ea-b0fe-0692f0e4befb(String), 2019-11-22 10:14:33.446(Timestamp), 3(Integer), 0(Integer)
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG o.c.b.e.i.p.e.J.selectNextJobsToExecute - <== Total: 0
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13011 closing existing command context
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.persistence - ENGINE-03006 Cache state after flush: [
2019-11-22 11:14:33	]
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committing...
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 committing the persistence session...
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committed...
2019-11-22 11:14:33	10:14:33.454 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:14:33	10:14:33.455 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:14:33	10:14:33.455 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------
2019-11-22 11:14:33	10:14:33.455 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14022 Acquired 0 jobs for process engine 'default': []
2019-11-22 11:14:33	10:14:33.455 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14011 Job acquisition thread sleeping for 59991 millis
2019-11-22 11:15:33	10:15:33.446 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14012 Job acquisition thread woke up
2019-11-22 11:15:33	10:15:33.446 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
2019-11-22 11:15:33	10:15:33.446 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13009 opening new command context
2019-11-22 11:15:33	10:15:33.446 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Opening JDBC Connection
2019-11-22 11:15:33	10:15:33.447 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Setting autocommit to false on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:15:33	10:15:33.447 [Thread-6] DEBUG 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.DEPLOYMENT_ID_ is null or ( RES.DEPLOYMENT_ID_ IN ( ? ) ) ) and ( ( RES.EXCLUSIVE_ = true 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_ = true) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = false ) LIMIT ? OFFSET ?
2019-11-22 11:15:33	10:15:33.448 [Thread-6] DEBUG o.c.b.e.i.p.e.J.selectNextJobsToExecute - ==> Parameters: 2019-11-22 10:15:33.446(Timestamp), 2019-11-22 10:15:33.446(Timestamp), 9845a42d-0d10-11ea-b0fe-0692f0e4befb(String), 2019-11-22 10:15:33.446(Timestamp), 3(Integer), 0(Integer)
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG o.c.b.e.i.p.e.J.selectNextJobsToExecute - <== Total: 0
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13011 closing existing command context
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.persistence - ENGINE-03006 Cache state after flush: [
2019-11-22 11:15:33	]
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committing...
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 committing the persistence session...
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG org.camunda.bpm.engine.tx - ENGINE-11002 firing event committed...
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Resetting autocommit to true on JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:15:33	10:15:33.454 [Thread-6] DEBUG o.a.i.t.jdbc.JdbcTransaction - Closing JDBC Connection [ProxyConnection[PooledConnection[org.postgresql.jdbc4.Jdbc4Connection@7ea89403]]]
2019-11-22 11:15:33	10:15:33.455 [Thread-6] DEBUG org.camunda.bpm.engine.cmd - ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------
2019-11-22 11:15:33	10:15:33.455 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14022 Acquired 0 jobs for process engine 'default': []
2019-11-22 11:15:33	10:15:33.455 [Thread-6] DEBUG org.camunda.bpm.engine.jobexecutor - ENGINE-14011 Job acquisition thread sleeping for 59991 millis

There are environment variable differences but nothing major. Mostly just url of the RabbitMQ, PostgreSQL, and LDAP servers.

This is damaging the performance of the app a tremendous amount, as for every LDAP lookup it spews out logs, slowing it down so that for example the admin page “List of users” page takes up to 8 seconds to load, where it on the local instance without the DEBUG logging takes maybe half a second if not faster.

Does anyone know any kind of trigger that could enable this weird behavior?

Any help is highly appreciated!

system · January 30, 2024, 12:03pm