TimerService: Timer interval stops after retry
----------------------------------------------
Key: JBAS-9457
URL:
https://issues.jboss.org/browse/JBAS-9457
Project: Legacy JBoss Application Server 6
Issue Type: Bug
Security Level: Public (Everyone can see)
Components: EJB
Affects Versions: 6.0.0.Final
Environment: jboss 6.0.0.Final, JDK
Reporter: Mario Klaver
Assignee: Carlo de Wolf
We are running into a problem concerning the EJB 3.x timer service. We are noticing the
timer doesn't fire timeouts anymore after an exception has occured and the retry of
the current timeout isn't finished before the new timeout should occur.
We attached two source file, which will demonstrate the problem.
In short:
The execute method in the attached example gets called every minute. The first time it
will throw an exception to enter the retry. When entering the retry it will sleep for 90
seconds to make sure it is not finished before the next timeout occurs.
After the retry finished, new timeouts will not occur. We would expect new timeouts after
the retry finished, but this doesn't happen. Can anyone explain why?
We run the example on:
- JBoss 6.0
- with JRE 1.6.0_26
Below you will find the logging:
15:57:16,004 INFO [timer.TimerTestBean] Executing TimerTestBean
15:57:16,004 INFO [timer.TimerTestBean] Throwing exception: [pool-13-thread-1]
15:57:16,004 ERROR [org.jboss.ejb3.timerservice.mk2.task.TimerTask] Error invoking timeout
for timer: [id=07edbaab-c7ee-4311-860b-0419a35a89d0
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@21fd3544
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 15:57:17 CET 2011 timerState=IN_TIMEOUT:javax.ejb.EJBException:
java.lang.RuntimeException: Screw you
at
org.jboss.ejb3.tx2.impl.CMTTxInterceptor.handleExceptionInOurTx(CMTTxInterceptor.java:183)
[:0.0.1]
at
org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:251)
[:0.0.1]
at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.required(CMTTxInterceptor.java:349)
[:0.0.1]
at org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invoke(CMTTxInterceptor.java:209)
[:0.0.1]
at
org.jboss.ejb3.tx2.aop.CMTTxInterceptorWrapper.invoke(CMTTxInterceptorWrapper.java:52)
[:0.0.1]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
[:1.0.0.GA]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:41)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.core.context.CurrentInvocationContextInterceptor.invoke(CurrentInvocationContextInterceptor.java:47)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
[:1.0.1]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.interceptor.EJB3TCCLInterceptor.invoke(EJB3TCCLInterceptor.java:86)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.singleton.aop.impl.AOPBasedInterceptorRegistry.intercept(AOPBasedInterceptorRegistry.java:110)
[:1.0.0-alpha-28]
at
org.jboss.ejb3.singleton.impl.container.SingletonContainer.invoke(SingletonContainer.java:206)
[:1.0.0-alpha-28]
at
org.jboss.ejb3.singleton.aop.impl.AOPBasedSingletonContainer.callTimeout(AOPBasedSingletonContainer.java:886)
[:1.0.0-alpha-28]
at
org.jboss.ejb3.timerservice.mk2.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:80)
[:1.0.0-alpha-13]
at org.jboss.ejb3.timerservice.mk2.task.TimerTask.run(TimerTask.java:127)
[:1.0.0-alpha-13]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
[:1.6.0_26]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[:1.6.0_26]
at java.util.concurrent.FutureTask.run(FutureTask.java:138) [:1.6.0_26]
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98)
[:1.6.0_26]
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206)
[:1.6.0_26]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[:1.6.0_26]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[:1.6.0_26]
at java.lang.Thread.run(Thread.java:680) [:1.6.0_26]
Caused by: java.lang.RuntimeException: Screw you
at timer.TimerTestBean.execute(TimerTestBean.java:26) [:]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_26]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[:1.6.0_26]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[:1.6.0_26]
at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_26]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.interceptors.container.ContainerMethodInvocationWrapper.invokeNext(ContainerMethodInvocationWrapper.java:72)
[:1.1.3]
at
org.jboss.ejb3.interceptors.aop.InterceptorSequencer.invoke(InterceptorSequencer.java:76)
[:1.1.3]
at
org.jboss.ejb3.interceptors.aop.InterceptorSequencer.aroundInvoke(InterceptorSequencer.java:62)
[:1.1.3]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [:1.6.0_26]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
[:1.6.0_26]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
[:1.6.0_26]
at java.lang.reflect.Method.invoke(Method.java:597) [:1.6.0_26]
at org.jboss.aop.advice.PerJoinpointAdvice.invoke(PerJoinpointAdvice.java:174)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.fillMethod(InvocationContextInterceptor.java:74)
[:1.1.3]
at
org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_fillMethod_1180675534.invoke(InvocationContextInterceptor_z_fillMethod_1180675534.java)
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.setup(InvocationContextInterceptor.java:90)
[:1.1.3]
at
org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_setup_1180675534.invoke(InvocationContextInterceptor_z_setup_1180675534.java)
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.async.impl.interceptor.AsynchronousServerInterceptor.invoke(AsynchronousServerInterceptor.java:128)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:62)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:56)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.concurrency.aop.interceptor.ContainerManagedConcurrencyInterceptor.invoke(ContainerManagedConcurrencyInterceptor.java:181)
[:1.0.0-alpha-4]
at
org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:86)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
[:1.7.17]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42) [:1.0.3]
at
org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
[jboss-aop.jar:2.2.1.GA]
at
org.jboss.ejb3.core.context.SessionInvocationContextAdapter.proceed(SessionInvocationContextAdapter.java:95)
[:1.7.17]
at
org.jboss.ejb3.tx2.impl.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:247)
[:0.0.1]
... 29 more
15:57:16,023 INFO [org.jboss.ejb3.timerservice.mk2.task.TimerTask] Timer:
[id=07edbaab-c7ee-4311-860b-0419a35a89d0
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@21fd3544
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 15:57:17 CET 2011 timerState=IN_TIMEOUT will be retried
15:57:16,023 INFO [org.jboss.ejb3.timerservice.mk2.task.TimerTask] Retrying timeout for
timer: [id=07edbaab-c7ee-4311-860b-0419a35a89d0
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@21fd3544
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 15:57:17 CET 2011 timerState=IN_TIMEOUT
15:57:16,024 INFO [timer.TimerTestBean] Executing TimerTestBean
15:57:16,024 INFO [timer.TimerTestBean] Sleeping 2 minutes: [pool-13-thread-1]
15:58:46,024 INFO [timer.TimerTestBean] Finished executing TimerTestBean
We added some more logging. As you can see, the state of the timer is RETRY_TIMEOUT until
the retry succeeds. After the TimerTestBean finishes the state is changed to ACTIVE.
However, no new timeouts arrive, even though nextExpiration=Tue Dec 06 17:36:00.
Our guess is that this is a bug in jboss 6.
Thanks in advance,
Regards,
Mario
17:35:00,024 INFO [org.jboss.ejb3.timerservice.mk2.task.TimerTask] Timer:
[id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=IN_TIMEOUT will be retried
17:35:00,024 INFO [org.jboss.ejb3.timerservice.mk2.task.TimerTask] Retrying timeout for
timer: [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=IN_TIMEOUT
17:35:00,025 INFO [timer.TimerTestBean] Executing TimerTestBean
17:35:00,025 INFO [timer.TimerTestBean] Sleeping 2 minutes: [pool-22-thread-1]
17:35:30,002 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=RETRY_TIMEOUT
17:36:00,002 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=RETRY_TIMEOUT
17:36:30,003 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=RETRY_TIMEOUT
17:36:30,025 INFO [timer.TimerTestBean] Finished executing TimerTestBean
17:37:00,003 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=ACTIVE
17:37:30,003 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=ACTIVE
17:38:00,004 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=ACTIVE
17:38:30,002 INFO [timer.PrintAllTimersBean] [id=f11091eb-67b7-4200-ba96-dc60d2c8751e
timedObjectId=jboss.j2ee:jar=timerTest.jar,name=TimerTestBean,service=EJB3
auto-timer?:true persistent?:false
timerService=org.jboss.ejb3.timerservice.mk2.TimerServiceImpl@7b4b5f0c
initialExpiration=Tue Dec 06 00:00:00 CET 2011 intervalDuration(in milli sec)=0
nextExpiration=Tue Dec 06 17:36:00 CET 2011 timerState=ACTIVE
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators:
https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see:
http://www.atlassian.com/software/jira