[jboss-jira] [JBoss JIRA] (AS7-4184) EJB 3.1 timer logs wrong exception on retry

EJB 3.1 timer logs wrong exception on retry ------------------------------------------- Key: AS7-4184 URL: https://issues.jboss.org/browse/AS7-4184 Project: Application Server 7 Issue Type: Bug Components: EE, EJB Affects Versions: 7.1.1.Final Environment: JbossAS 7.1.1.Final, java 1.6.0_30 Reporter: Samuli Saarinen Assignee: Stuart Douglas If exception is thrown in timer jboss timer service attempts to retry one. If exception is also thrown on retry the exception thrown during the first attempt is reported in server logs regardless of the exception that is actually thrown. Following example class demonstrates the problem where stacktrace of the IllegalArgumentException is printed in the logs for timer execution and the following retry {code:java} @Singleton @Startup public class SchduledJob { int fails = 0; @Schedule(hour="*", minute="*", second="*/15") public void failing(Timer timer) { fails++; System.out.println("current fails " + fails); if(fails < 6) { if(fails % 2 == 0) { System.out.println("throwing rte"); throw new RuntimeException("rte " + fails); } else { System.out.println("throwing iae"); throw new IllegalArgumentException("iae " + fails); } } System.out.println("OK " +fails); } } {code} And the related server log {noformat} 13:28:45,000 INFO [stdout] (EJB default - 1) current fails 1 13:28:45,000 INFO [stdout] (EJB default - 1) throwing iae 13:28:45,000 ERROR [org.jboss.as.ejb3] (EJB default - 1) JBAS014120: Error invoking timeout for timer: [id=eb9c21af-4277-4ecc-b43e-1e4aa5756a69 timedObjectId=JBossTimerBug.JBossTimerBug.SchduledJob auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1fd0943 initialExpiration=Thu Mar 15 00:00:00 EET 2012 intervalDuration(in milli sec)=0 nextExpiration=Thu Mar 15 13:29:00 EET 2012 timerState=IN_TIMEOUT: javax.ejb.EJBException: java.lang.IllegalArgumentException: iae 1 at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInOurTx(CMTTxInterceptor.java:166) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.TimerCMTTxInterceptor.handleExceptionInOurTx(TimerCMTTxInterceptor.java:52) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:230) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.timerservice.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:60) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:132) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [rt.jar:1.6.0_30] at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [rt.jar:1.6.0_30] at java.util.concurrent.FutureTask.run(FutureTask.java:138) [rt.jar:1.6.0_30] at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_30] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_30] at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_30] at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.0.0.GA.jar:2.0.0.GA] Caused by: java.lang.IllegalArgumentException: iae 1 at com.remion.test.ee6.SchduledJob.failing(SchduledJob.java:34) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_30] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [rt.jar:1.6.0_30] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [rt.jar:1.6.0_30] at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_30] at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:34) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.concurrency.ContainerManagedConcurrencyInterceptor.processInvocation(ContainerManagedConcurrencyInterceptor.java:104) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:228) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] ... 22 more 13:28:45,093 INFO [org.jboss.as.ejb3] (EJB default - 1) JBAS014121: Timer: [id=eb9c21af-4277-4ecc-b43e-1e4aa5756a69 timedObjectId=JBossTimerBug.JBossTimerBug.SchduledJob auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1fd0943 initialExpiration=Thu Mar 15 00:00:00 EET 2012 intervalDuration(in milli sec)=0 nextExpiration=Thu Mar 15 13:29:00 EET 2012 timerState=IN_TIMEOUT will be retried 13:28:45,093 INFO [org.jboss.as.ejb3] (EJB default - 1) JBAS014123: Retrying timeout for timer: [id=eb9c21af-4277-4ecc-b43e-1e4aa5756a69 timedObjectId=JBossTimerBug.JBossTimerBug.SchduledJob auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1fd0943 initialExpiration=Thu Mar 15 00:00:00 EET 2012 intervalDuration(in milli sec)=0 nextExpiration=Thu Mar 15 13:29:00 EET 2012 timerState=IN_TIMEOUT 13:28:45,109 INFO [stdout] (EJB default - 1) current fails 2 13:28:45,109 INFO [stdout] (EJB default - 1) throwing rte 13:28:45,109 ERROR [org.jboss.as.ejb3] (EJB default - 1) JBAS014122: Error during retrying timeout for timer: [id=eb9c21af-4277-4ecc-b43e-1e4aa5756a69 timedObjectId=JBossTimerBug.JBossTimerBug.SchduledJob auto-timer?:true persistent?:true timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1fd0943 initialExpiration=Thu Mar 15 00:00:00 EET 2012 intervalDuration(in milli sec)=0 nextExpiration=Thu Mar 15 13:29:00 EET 2012 timerState=RETRY_TIMEOUT: javax.ejb.EJBException: java.lang.IllegalArgumentException: iae 1 at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInOurTx(CMTTxInterceptor.java:166) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.TimerCMTTxInterceptor.handleExceptionInOurTx(TimerCMTTxInterceptor.java:52) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:230) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:304) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:190) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:43) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.timerservice.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:60) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:132) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [rt.jar:1.6.0_30] at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303) [rt.jar:1.6.0_30] at java.util.concurrent.FutureTask.run(FutureTask.java:138) [rt.jar:1.6.0_30] at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_30] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_30] at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_30] at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.0.0.GA.jar:2.0.0.GA] Caused by: java.lang.IllegalArgumentException: iae 1 at com.remion.test.ee6.SchduledJob.failing(SchduledJob.java:34) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.6.0_30] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [rt.jar:1.6.0_30] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [rt.jar:1.6.0_30] at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_30] at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:34) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.concurrency.ContainerManagedConcurrencyInterceptor.processInvocation(ContainerManagedConcurrencyInterceptor.java:104) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.1.Final.jar:1.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:228) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] ... 22 more {noformat}