[jboss-jira] [JBoss JIRA] (JBAS-9458) TimerService: Timer interval stops after retry
Wolf-Dieter Fink (Updated) (JIRA)
jira-events at lists.jboss.org
Tue Dec 13 06:48:09 EST 2011
[ https://issues.jboss.org/browse/JBAS-9458?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Wolf-Dieter Fink updated JBAS-9458:
-----------------------------------
Labels: community jboss7 timerservice (was: community jboss6 timerservice)
Assignee: Wolf-Dieter Fink
Affects Version/s: No Release
(was: 6.0.0.Final)
Environment: jboss 7.1.0.Beta1b (was: jboss 6.0.0.Final, JDK_1.6.0_26)
Forum Reference: http://community.jboss.org/thread/175879
> TimerService: Timer interval stops after retry
> ----------------------------------------------
>
> Key: JBAS-9458
> URL: https://issues.jboss.org/browse/JBAS-9458
> Project: Legacy JBoss Application Server 6
> Issue Type: Bug
> Security Level: Public(Everyone can see)
> Components: EJB
> Affects Versions: No Release
> Environment: jboss 7.1.0.Beta1b
> Reporter: Wolf-Dieter Fink
> Assignee: Wolf-Dieter Fink
> Labels: community, jboss7, timerservice
> Fix For: Open To Community
>
>
> 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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
More information about the jboss-jira
mailing list