cancel
Showing results for 
Search instead for 
Did you mean: 

Async tasks do not always log proper error when failing

mnorman
Champ in-the-making
Champ in-the-making
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.
11 REPLIES 11

frederikherema1
Star Contributor
Star Contributor
Okay, always great to hear feedback on these kind of tricky issues

mnorman
Champ in-the-making
Champ in-the-making
I was able to verify this solution worked locally.