Async tasks do not always log proper error when failing

[mnorman]

Whenever an async task fails with a "No value for key" exception, the original error doesn't get logged properly. Instead, it gets logged to stderr. We are using Tomcat, so that means this error goes to catalina.out.

We are using async tasks in a number of places, and some of those places call a delegate, which can cause an exception to be thrown. We've tried to handle all those cases, but sometimes one still slips through.

If an exception gets thrown from the delegate, here is the exception that appears in our logs:
<blockcode>
java.lang.IllegalStateException: No value for key [org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@519ada6e] bound to thread [pool-39-thread-39]
        at org.springframework.transaction.support.TransactionSynchronizationManager.unbindResource(TransactionSynchronizationManager.java:209) ~[spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.mybatis.spring.SqlSessionUtils$SqlSessionSynchronization.suspend(SqlSessionUtils.java:229) ~[mybatis-spring-1.2.1.jar:1.2.1]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.doSuspendSynchronization(AbstractPlatformTransactionManager.java:667) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.suspend(AbstractPlatformTransactionManager.java:570) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:419) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:128) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45) [activiti-spring-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.jobexecutor.FailedJobListener.execute(FailedJobListener.java:45) ~[activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.spring.SpringTransactionContext$4.afterCompletion(SpringTransactionContext.java:97) [activiti-spring-5.14-RMN-01.jar:5.14-RMN-01]
        at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:168) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.invokeAfterCompletion(AbstractPlatformTransactionManager.java:994) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCompletion(AbstractPlatformTransactionManager.java:969) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:873) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:823) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.TransactionTemplate.rollbackOnException(TransactionTemplate.java:162) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:135) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45) [activiti-spring-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:46) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_45]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_45]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_45]
<blockcode>

That exception is not so useful. The real exception is the "cause" that is part of the following exception, which gets written to stderr:
<blockcode>
Exception in thread "pool-41-thread-9" org.activiti.engine.ActivitiException: Job 02741b34-531c-11e3-b4fe-12314000c877 failed
        at org.activiti.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:83)
        at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
        at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:131)
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
        at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:46)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
Caused by: …
<blockcode>

This stack trace is what we really need to debug the issue.

In addition, and this may be related, the async task job keeps getting called, every 5 minutes. I thought there was supposed to be a limit of 3 times, but the retry counter on the job never gets decremented, so it just keeps throwing the same error over and over and over.

[mnorman]

Sorry about the format in the original message.

Exception from the logs:
<blockcode>
java.lang.IllegalStateException: No value for key [org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@519ada6e] bound to thread [pool-39-thread-39]
        at org.springframework.transaction.support.TransactionSynchronizationManager.unbindResource(TransactionSynchronizationManager.java:209) ~[spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.mybatis.spring.SqlSessionUtils$SqlSessionSynchronization.suspend(SqlSessionUtils.java:229) ~[mybatis-spring-1.2.1.jar:1.2.1]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.doSuspendSynchronization(AbstractPlatformTransactionManager.java:667) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.suspend(AbstractPlatformTransactionManager.java:570) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:419) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:128) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45) [activiti-spring-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.jobexecutor.FailedJobListener.execute(FailedJobListener.java:45) ~[activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.spring.SpringTransactionContext$4.afterCompletion(SpringTransactionContext.java:97) [activiti-spring-5.14-RMN-01.jar:5.14-RMN-01]
        at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:168) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.invokeAfterCompletion(AbstractPlatformTransactionManager.java:994) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCompletion(AbstractPlatformTransactionManager.java:969) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:873) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:823) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.TransactionTemplate.rollbackOnException(TransactionTemplate.java:162) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:135) [spring-tx-3.2.4.RELEASE.jar:3.2.4.RELEASE]
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45) [activiti-spring-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:46) [activiti-engine-5.14-RMN-01.jar:5.14-RMN-01]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_45]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_45]
        at java.lang.Thread.run(Thread.java:744) [na:1.7.0_45]
</blockcode>

That exception is not so useful. The real exception is the "cause" that is part of the following exception, which gets written to stderr:
<blockcode>
Exception in thread "pool-41-thread-9" org.activiti.engine.ActivitiException: Job 02741b34-531c-11e3-b4fe-12314000c877 failed
        at org.activiti.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:83)
        at org.activiti.engine.impl.interceptor.CommandInvoker.execute(CommandInvoker.java:24)
        at org.activiti.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:57)
        at org.activiti.spring.SpringTransactionInterceptor$1.doInTransaction(SpringTransactionInterceptor.java:47)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:131)
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
        at org.activiti.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:46)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
Caused by: …
</blockcode>

This stack trace is what we really need to debug the issue.

In addition, and this may be related, the async task job keeps getting called, every 5 minutes. I thought there was supposed to be a limit of 3 times, but the retry counter on the job never gets decremented, so it just keeps throwing the same error over and over and over.

[trademak]

This error seems to prevent the job entity from being update and that's why it doesn't get decremented. Do you know what's causing this error, because you didn't include the whole stacktrace. Which version of Activiti our you using? I'm particularly interested in the exception causing this problem, because the job executor should also work with failing service task logic.

Best regards,

[mnorman]

We're using Activiti 5.14. Sorry, I sent all of the stack trace except the root cause. Here's the Activiti lines from one of our causes:

Caused by: (our exception redacted)
        at org.activiti.engine.impl.delegate.JavaDelegateInvocation.invoke(JavaDelegateInvocation.java:34)
        at org.activiti.engine.impl.delegate.DelegateInvocation.proceed(DelegateInvocation.java:37)
        at org.activiti.engine.impl.delegate.DefaultDelegateInterceptor.handleInvocation(DefaultDelegateInterceptor.java:25)
        at org.activiti.engine.impl.bpmn.behavior.ServiceTaskDelegateExpressionActivityBehavior.execute(ServiceTaskDelegateExpressionActivityBehavior.java:75)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationActivityExecute.execute(AtomicOperationActivityExecute.java:45)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerStart.eventNotificationsCompleted(AtomicOperationTransitionNotifyListenerStart.java:52)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:56)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionCreateScope.execute(AtomicOperationTransitionCreateScope.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerTake.execute(AtomicOperationTransitionNotifyListenerTake.java:66)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionDestroyScope.execute(AtomicOperationTransitionDestroyScope.java:116)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerEnd.eventNotificationsCompleted(AtomicOperationTransitionNotifyListenerEnd.java:36)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:56)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.take(ExecutionEntity.java:367)
        at org.activiti.engine.impl.bpmn.behavior.BpmnActivityBehavior.performOutgoingBehavior(BpmnActivityBehavior.java:105)
        at org.activiti.engine.impl.bpmn.behavior.BpmnActivityBehavior.performDefaultOutgoingBehavior(BpmnActivityBehavior.java:54)
        at org.activiti.engine.impl.bpmn.behavior.FlowNodeActivityBehavior.leave(FlowNodeActivityBehavior.java:44)
        at org.activiti.engine.impl.bpmn.behavior.AbstractBpmnActivityBehavior.leave(AbstractBpmnActivityBehavior.java:47)
        at org.activiti.engine.impl.bpmn.behavior.ScriptTaskActivityBehavior.execute(ScriptTaskActivityBehavior.java:83)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationActivityExecute.execute(AtomicOperationActivityExecute.java:45)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerStart.eventNotificationsCompleted(AtomicOperationTransitionNotifyListenerStart.java:52)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:56)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionCreateScope.execute(AtomicOperationTransitionCreateScope.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerTake.execute(AtomicOperationTransitionNotifyListenerTake.java:66)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionDestroyScope.execute(AtomicOperationTransitionDestroyScope.java:116)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerEnd.eventNotificationsCompleted(AtomicOperationTransitionNotifyListenerEnd.java:36)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:56)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.take(ExecutionEntity.java:367)
        at org.activiti.engine.impl.bpmn.behavior.BpmnActivityBehavior.performOutgoingBehavior(BpmnActivityBehavior.java:105)
        at org.activiti.engine.impl.bpmn.behavior.BpmnActivityBehavior.performDefaultOutgoingBehavior(BpmnActivityBehavior.java:54)
        at org.activiti.engine.impl.bpmn.behavior.FlowNodeActivityBehavior.leave(FlowNodeActivityBehavior.java:44)
        at org.activiti.engine.impl.bpmn.behavior.AbstractBpmnActivityBehavior.leave(AbstractBpmnActivityBehavior.java:47)
        at org.activiti.engine.impl.bpmn.behavior.ServiceTaskExpressionActivityBehavior.execute(ServiceTaskExpressionActivityBehavior.java:49)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationActivityExecute.execute(AtomicOperationActivityExecute.java:45)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerStart.eventNotificationsCompleted(AtomicOperationTransitionNotifyListenerStart.java:52)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:56)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionCreateScope.execute(AtomicOperationTransitionCreateScope.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerTake.execute(AtomicOperationTransitionNotifyListenerTake.java:66)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionDestroyScope.execute(AtomicOperationTransitionDestroyScope.java:116)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AtomicOperationTransitionNotifyListenerEnd.eventNotificationsCompleted(AtomicOperationTransitionNotifyListenerEnd.java:36)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:56)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.pvm.runtime.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:49)
        at org.activiti.engine.impl.interceptor.CommandContext.performOperation(CommandContext.java:88)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:532)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:527)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.take(ExecutionEntity.java:367)
        at org.activiti.engine.impl.bpmn.behavior.BpmnActivityBehavior.performOutgoingBehavior(BpmnActivityBehavior.java:105)
        at org.activiti.engine.impl.bpmn.behavior.BpmnActivityBehavior.performDefaultOutgoingBehavior(BpmnActivityBehavior.java:54)
        at org.activiti.engine.impl.bpmn.behavior.FlowNodeActivityBehavior.leave(FlowNodeActivityBehavior.java:44)
        at org.activiti.engine.impl.bpmn.behavior.AbstractBpmnActivityBehavior.leave(AbstractBpmnActivityBehavior.java:47)
        at org.activiti.engine.impl.bpmn.behavior.IntermediateCatchEventActivityBehavior.signal(IntermediateCatchEventActivityBehavior.java:27)
        at org.activiti.engine.impl.persistence.entity.ExecutionEntity.signal(ExecutionEntity.java:350)
        at org.activiti.engine.impl.jobexecutor.TimerCatchIntermediateEventJobHandler.execute(TimerCatchIntermediateEventJobHandler.java:46)
        at org.activiti.engine.impl.persistence.entity.JobEntity.execute(JobEntity.java:79)
        at org.activiti.engine.impl.persistence.entity.TimerEntity.execute(TimerEntity.java:62)
        at org.activiti.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:71)
        … 12 more

[trademak]

Hi,

Ok, so it's failing in the execution of the service task logic (Because it's pointing to this line):

delegateInstance.execute((DelegateExecution) execution);

Is it throwing a custom exception class from your code? Does this class extend RuntimeException?
On which line in your service task logic is it failing?

Best regards,

[mnorman]

It is throwing a custom exception from our code, and that exception extends IllegalStateException which does extend RuntimeException. We know which line is failing in our service, but I didn't include those lines since they are specific to our code and it's not really important. I would expect that any exception in our service code should cause the job to be retried 3 times and then it should stop retrying.

[jbarrez]

Ok, just to recap then:

- The exception is logged to standard out instead of the error log?
- Do you see the job being retried 3 times?
- What is the value of the retry count in the database?

[mnorman]

- Yes, the exception is logged to standard out instead of the error log.
- The job is retried every 5 minutes infinitely until we delete it. It is not limited to 3 times.
- The value of the retry count on the job in the DB is always 3

This only appears to be a problem with async step jobs. Timer jobs seem to do the right thing, though we don't get nearly as many errors in our services with timer jobs.

[frederikherema1]

Seems to be an issue with the transaction synchronisation adapter. When the job fails, a synchrnisation adapter is added to the current transaction. When this is called (on rollback), it will fetch a new transaction and context (REQUIRES_NEW) from the transactionManager and use that transaction to decrement the retry-count and populate the exception-field. The 'after completion' of the failing transaction is called successfully, but using the NEW transaction fails: java.lang.IllegalStateException: No value for key [org.apache.ibatis.session.defaults.DefaultSqlSessionFactory@519ada6e] bound to thread.

So that fails as well, NOT decrementing the retry-count an keeping the job marked as "LOCKED". Once the lock-timeout expires (default is 5 minutes) it will be picked up by the job-executor again. Failing again, keeping it locked again.

I saw a simmilar issue in the Alfresco-integration, with mybatis and "No value for key  … bound to thread". See https://issues.alfresco.com/jira/browse/ALF-9096. The actual problem is that the transaction synchronisation adapter activiti uses, was called AFTER the one myBatis uses to unbind the connection from the current thread-context (or something like this). The solution was to alter the order the adapter was called in. To do this, you'll need to set the "transactionSynchronizationAdapterOrder" property on the SpringProcessEngineConfiguration to a value LOWER than the one that is causing the resource to be unbound.

In case of alfresco, we're using this value, minus 100 (org.springframework.orm.hibernate3.SessionFactoryUtils):


/**
  * Order value for TransactionSynchronization objects that clean up Hibernate Sessions.
  * Returns DataSourceUtils.CONNECTION_SYNCHRONIZATION_ORDER - 100
  * to execute Session cleanup before JDBC Connection cleanup, if any.
  * @see org.springframework.jdbc.datasource.DataSourceUtils#CONNECTION_SYNCHRONIZATION_ORDER
  */
public static final int SESSION_SYNCHRONIZATION_ORDER =
   DataSourceUtils.CONNECTION_SYNCHRONIZATION_ORDER - 100;

And a class that extends the SpringProcessEngineConfiguration, we use this (However, can also be done using a plain SpringProcessEngineConfiguration and just setting the property in XML):


/**
* @author Nick Smith
* @author Frederik Heremans
* @since 3.4.e
*/
public class AlfrescoProcessEngineConfiguration extends SpringProcessEngineConfiguration
{
    private List<VariableType> customTypes;
    private NodeService unprotectedNodeService;
   
    public AlfrescoProcessEngineConfiguration()
    {
        // Make sure the synchornizationAdapter is run before the AlfrescoTransactionSupport (and also before the
        // myBatis synchonisation, which unbinds the neccesairy sqlSession used by the JobFailedListener)
        this.transactionSynchronizationAdapterOrder = AlfrescoTransactionSupport.SESSION_SYNCHRONIZATION_ORDER - 100;
    }

The actual number you should use depends on what other ORM/DB frameworks you're using, but I think the best bet whould be to go below the DataSourceUtils.CONNECTION_SYNCHRONIZATION_ORDER value.

Hope this helps. I remember myself digging into this for  quite a couple of hours chasing down this issue, so I hope it's the same solution for your problem.

[mnorman]

Thanks, I'll try it out and report back.