AnsweredAssumed Answered

Async tasks do not always log proper error when failing

Question asked by mnorman on Dec 20, 2013
Latest reply on Feb 26, 2014 by 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.

Outcomes