Sporadic exception- ENGINE-16004 Exception while closing command context

Dear all

We see this error sometimes in our camunda setup. We use postgresql in a kubernetes cluster setup. We have until now found no root cause in DB logs. We hope that some of you might have experienced this issue before. And as already mentioned, this error is sporadic. So we cannot fully replicate it following the same steps.

2:57:44.648 [Default Executor-thread-256362] DEBUG com.intrasoft.hermes.cwm.app.health.camunda.CamundaEngineConnectionHealthCheck [trace:{}] - Camunda Engine check succeeded
[AUDIT ] J2CA0056I: The Connection Manager received a fatal connection error from the Resource Adapter for resource jdbc/camundaDS. The exception is: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.:java.io.EOFException
12:57:50.673 [Default Executor-thread-1] ERROR org.camunda.bpm.engine.context [trace:{}] - ENGINE-16004 Exception while closing command context: An exception occurred in the persistence layer. Please check the server logs for a detailed message and the entire exception stack trace.
org.camunda.bpm.engine.ProcessEngineException: An exception occurred in the persistence layer. Please check the server logs for a detailed message and the entire exception stack trace.
at org.camunda.bpm.engine.impl.util.ExceptionUtil.wrapPersistenceException(ExceptionUtil.java:263) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.util.ExceptionUtil.doWithExceptionWrapper(ExceptionUtil.java:257) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.db.sql.DbSqlSession.executeSelectList(DbSqlSession.java:111) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.db.sql.DbSqlSession.selectList(DbSqlSession.java:103) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.db.entitymanager.DbEntityManager.selectListWithRawParameter(DbEntityManager.java:182) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.db.entitymanager.DbEntityManager.selectList(DbEntityManager.java:174) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.persistence.entity.ProcessDefinitionManager.findLatestProcessDefinitionsByKey(ProcessDefinitionManager.java:91) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.persistence.entity.ProcessDefinitionManager.findLatestProcessDefinitionByKey(ProcessDefinitionManager.java:69) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.persistence.entity.ProcessDefinitionManager.findLatestDefinitionByKey(ProcessDefinitionManager.java:405) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.persistence.entity.ProcessDefinitionManager.findLatestDefinitionByKey(ProcessDefinitionManager.java:48) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.persistence.deploy.cache.ResourceDefinitionCache.findDeployedLatestDefinitionByKey(ResourceDefinitionCache.java:66) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.persistence.deploy.cache.DeploymentCache.findDeployedLatestProcessDefinitionByKey(DeploymentCache.java:86) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.cmd.GetDeployedProcessDefinitionCmd.findByKey(GetDeployedProcessDefinitionCmd.java:87) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.cmd.GetDeployedProcessDefinitionCmd.find(GetDeployedProcessDefinitionCmd.java:74) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.cmd.GetDeployedProcessDefinitionCmd.execute(GetDeployedProcessDefinitionCmd.java:56) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.cmd.StartProcessInstanceCmd.execute(StartProcessInstanceCmd.java:50) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.cmd.StartProcessInstanceCmd.execute(StartProcessInstanceCmd.java:38) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.interceptor.CommandExecutorImpl.execute(CommandExecutorImpl.java:28) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:110) [camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.interceptor.ProcessApplicationContextInterceptor.execute(ProcessApplicationContextInterceptor.java:70) [camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.interceptor.CommandCounterInterceptor.execute(CommandCounterInterceptor.java:35) [camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33) [camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.ProcessInstantiationBuilderImpl.executeWithVariablesInReturn(ProcessInstantiationBuilderImpl.java:166) [camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.ProcessInstantiationBuilderImpl.executeWithVariablesInReturn(ProcessInstantiationBuilderImpl.java:137) [camunda-engine-7.15.0.jar:7.15.0]
at com.intrasoft.ermis.common.bpmn.service.camunda.BpmnEngineCamunda.createProcessInstanceByProcessId(BpmnEngineCamunda.java:66) [bpmn-engine-camunda-1.0.3.jar:?]
at com.intrasoft.hermes.cwm.additionalmessage.service.process.HandleAdditionalMessageFacade.initProcessInstance(HandleAdditionalMessageFacade.java:74) [additional-message-core-4.1.5.jar:?]
at com.intrasoft.hermes.cwm.additionalmessage.service.process.HandleAdditionalMessageFacade$Proxy$$$WeldSubclass.initProcessInstance$$super(Unknown Source) [additional-message-core-4.1.5.jar:?]
at sun.reflect.GeneratedMethodAccessor1028.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_282]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_282]
at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at com.intrasoft.ermis.common.log.DomainServiceLoggerInterceptor.interceptMethod(DomainServiceLoggerInterceptor.java:28) [ermis-logger-cdi-impl-1.0.3.jar:?]
at sun.reflect.GeneratedMethodAccessor184.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_282]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_282]
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.NonTerminalAroundInvokeInvocationContext.proceedInternal(NonTerminalAroundInvokeInvocationContext.java:66) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.contexts.activator.AbstractActivateRequestContextInterceptor.invoke(AbstractActivateRequestContextInterceptor.java:55) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at sun.reflect.GeneratedMethodAccessor169.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_282]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_282]
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at com.intrasoft.hermes.cwm.additionalmessage.service.process.HandleAdditionalMessageFacade$Proxy$
$$WeldSubclass.initProcessInstance(Unknown Source) [additional-message-core-4.1.5.jar:?]
at com.intrasoft.hermes.cwm.additionalmessage.service.process.HandleAdditionalMessageFacade$Proxy$
$$WeldClientProxy.initProcessInstance(Unknown Source) [additional-message-core-4.1.5.jar:?]
at com.intrasoft.hermes.cwm.additionalmessage.ada
pter.inbound.kafka.handler.AdditionalMessageArrivedHandler.runService(AdditionalMessageArrivedHandler.java:57) [additional-message-adapter-4.1.5.jar:?]
at com.intrasoft.hermes.cwm.additionalmessage.adapter.inbound.kafka.handler.AdditionalMessageArrivedHandler$Proxy$
$$WeldSubclass.runService$$super(Unknown Source) [additional-message-adapter-4.1.5.jar:?]
at sun.reflect.GeneratedMethodAccessor1026.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_282]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_282]
at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at com.intrasoft.ermis.common.kafka.log.KafkaHeaderInterceptor.interceptMethod(KafkaHeaderInterceptor.java:34) [kafka-common-1.0.3.jar:?]
at sun.reflect.GeneratedMethodAccessor1025.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_282]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_282]
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.NonTerminalAroundInvokeInvocationContext.proceedInternal(NonTerminalAroundInvokeInvocationContext.java:66) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.contexts.activator.AbstractActivateRequestContextInterceptor.invoke(AbstractActivateRequestContextInterceptor.java:61) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at sun.reflect.GeneratedMethodAccessor169.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_282]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_282]
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) [com.ibm.ws.org.jboss.weld3_1.0.50.jar:3.1.4.Final]
at com.intrasoft.hermes.cwm.additionalmessage.adapter.inbound.kafka.handler.AdditionalMessageArrivedHandler$Proxy$
$$WeldSubclass.runService(Unknown Source) [additional-message-adapter-4.1.5.jar:?]
at com.intrasoft.ermis.common.kafka.generic.AbstractSequentialKafkaConsumer.processRecord(AbstractSequentialKafkaConsumer.java:138) [kafka-common-1.0.3.jar:?]
at com.intrasoft.ermis.common.kafka.generic.AbstractSequentialKafkaConsumer.lambda$consumeMessages$0(AbstractSequentialKafkaConsumer.java:116) [kafka-common-1.0.3.jar:?]
at com.intrasoft.ermis.common.kafka.generic.AbstractSequentialKafkaConsumer$$Lambda$569/0x00000000e02375a0.accept(Unknown Source) [kafka-common-1.0.3.jar:?]
at java.lang.Iterable.forEach(Iterable.java:75) [?:1.8.0_282]
at com.intrasoft.ermis.common.kafka.generic.AbstractSequentialKafkaConsumer.consumeMessages(AbstractSequentialKafkaConsumer.java:116) [kafka-common-1.0.3.jar:?]
at com.intrasoft.ermis.common.kafka.generic.AbstractSequentialKafkaConsumer.run(AbstractSequentialKafkaConsumer.java:72) [kafka-common-1.0.3.jar:?]
at com.ibm.ws.threading.internal.PolicyTaskFutureImpl.run(PolicyTaskFutureImpl.java:711) [com.ibm.ws.threading_1.1.50.jar:?]
at com.ibm.ws.threading.internal.PolicyExecutorImpl.runTask(PolicyExecutorImpl.java:1158) [com.ibm.ws.threading_1.1.50.jar:?]
at com.ibm.ws.threading.internal.PolicyExecutorImpl$GlobalPoolTask.run(PolicyExecutorImpl.java:190) [com.ibm.ws.threading_1.1.50.jar:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_282]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_282]
at java.lang.Thread.run(Thread.java:823) [?:1.8.0_282]
Caused by: org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
### The error may exist in org/camunda/bpm/engine/impl/mapping/entity/ProcessDefinition.xml
### The error may involve org.camunda.bpm.engine.impl.persistence.entity.ProcessDefinitionEntity.selectLatestProcessDefinitionByKey-Inline
### The error occurred while setting parameters
### SQL: select * from ACT_RE_PROCDEF p1 inner join (select KEY
, TENANT_ID
, max(VERSION_) as MAX_VERSION from ACT_RE_PROCDEF RES where KEY_ = ? group by TENANT_ID_, KEY_) p2 on p1.KEY_ = p2.KEY_ where p1.VERSION_ = p2.MAX_VERSION and (p1.TENANT_ID_ = p2.TENANT_ID_ or (p1.TENANT_ID_ is null and p2.TENANT_ID_ is null))
### Cause: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30) ~[mybatis-3.5.6.jar:3.5.6]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:149) ~[mybatis-3.5.6.jar:3.5.6]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:140) ~[mybatis-3.5.6.jar:3.5.6]
at org.camunda.bpm.engine.impl.db.sql.DbSqlSession.lambda$executeSelectList$1(DbSqlSession.java:111) ~[camunda-engine-7.15.0.jar:7.15.0]
at org.camunda.bpm.engine.impl.db.sql.DbSqlSession$$Lambda$336/0x00000000e909c210.get(Unknown Source) ~[?:?]
at org.camunda.bpm.engine.impl.util.ExceptionUtil.doWithExceptionWrapper(ExceptionUtil.java:254) ~[camunda-engine-7.15.0.jar:7.15.0]
… 86 more
Caused by: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.

org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.:java.io.EOFException

A quick search indicates this could be caused by a driver version not matching the database version (though I would suspect if this was the case you’d see more than just sporadic issues).

What version of PostgreSQL are you using? See here for supported environments for Camunda Platform 7.15.

What distribution of Camunda Platform are you using? My assumption given your Kubernetes cluster was the camunda/camunda-bpm-platform:7.15.0 docker image.

Hi jhihliotti

Thank you for your reply.
We are using Postgres 12 and Camunda version 7.15.

This is a sporadic error, but we seem to always be able to replicate it by having the environment beeing idle for some hours and then try to reproduce it.

Does this part of the exception give you anything?

### The error may involve org.camunda.bpm.engine.impl.persistence.entity.ProcessDefinitionEntity.selectLatestProcessDefinitionByKey-Inline
### The error occurred while setting parameters
### SQL: select * from ACT_RE_PROCDEF p1 inner join (select KEY_, TENANT_ID_, max(VERSION_) as MAX_VERSION from ACT_RE_PROCDEF RES where KEY_ = ? group by TENANT_ID_, KEY_) p2 on p1.KEY_ = p2.KEY_ where p1.VERSION_ = p2.MAX_VERSION and (p1.TENANT_ID_ = p2.TENANT_ID_ or (p1.TENANT_ID_ is null and p2.TENANT_ID_ is null))
### Cause: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.

Thanks.

Tough to say. Could easily be an unreliable connection to the database. Can you post full logs from Camunda and from the DB? There may be additional clues.

The camunda/camunda-bpm-platform:7.15.0 image ships with postgresql-9.4.1212.jar which seems a touch old. You may have better luck with a newer driver… but, like I said, tough to say.