[jboss-jira] [JBoss JIRA] (WFLY-3630) NonPersistentIntervalTimerManagementTestCase fails sometimes

[Frank Langelage (JIRA)]

    [ https://issues.jboss.org/browse/WFLY-3630?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12991497#comment-12991497 ] 

Frank Langelage commented on WFLY-3630:
---------------------------------------

More information:
I added some log statements to the testcase, in method testSuspendAndTrigger and in Timeout method of the bean.
Usually I see something like this:
07:38:53,024 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) createTimer
07:38:53,040 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) triggerTimer
07:38:53,054 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.IntervalTimerBean] (management-handler-thread - 4) booom: [id=6397e6f9-e7f7-4a84-aa58-d3f9d02d8b43 timedObjectId=ejb-mgmt-timers.ejb-mgmt-timers.IntervalTimerBean auto-timer?:false persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl at 1734190 initialExpiration=Fri Aug 08 07:38:56 CEST 2014 intervalDuration(in milli sec)=3000 nextExpiration=Fri Aug 08 07:38:59 CEST 2014 timerState=IN_TIMEOUT info=NonPersistentIntervalTimerCLITestCase
07:38:53,063 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) suspendTimer
07:38:53,070 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) waitOverTimer
07:38:57,080 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) activateTimer
07:38:57,089 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) waitOnTimeout
07:38:59,038 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.IntervalTimerBean] (EJB default - 7) booom: [id=6397e6f9-e7f7-4a84-aa58-d3f9d02d8b43 timedObjectId=ejb-mgmt-timers.ejb-mgmt-timers.IntervalTimerBean auto-timer?:false persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl at 1734190 initialExpiration=Fri Aug 08 07:38:56 CEST 2014 intervalDuration(in milli sec)=3000 nextExpiration=Fri Aug 08 07:39:02 CEST 2014 timerState=IN_TIMEOUT info=NonPersistentIntervalTimerCLITestCase

But for a failed test I see:
01:08:11,368 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) createTimer
01:08:11,368 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) triggerTimer
01:08:11,368 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.IntervalTimerBean] (management-handler-thread - 3) booom: [id=467f7f53-a6c7-4abe-9d28-63da530eeda6 timedObjectId=ejb-mgmt-timers.ejb-mgmt-timers.IntervalTimerBean auto-timer?:false persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl at 5931ef88 initialExpiration=Fri Aug 08 01:08:14 CEST 2014 intervalDuration(in milli sec)=3000 nextExpiration=Fri Aug 08 01:08:14 CEST 2014 timerState=IN_TIMEOUT info=NonPersistentIntervalTimerCLITestCase
01:08:11,368 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) suspendTimer
01:08:11,368 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) waitOverTimer
01:08:15,410 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) activateTimer
01:08:15,410 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.IntervalTimerBean] (EJB default - 3) booom: [id=467f7f53-a6c7-4abe-9d28-63da530eeda6 timedObjectId=ejb-mgmt-timers.ejb-mgmt-timers.IntervalTimerBean auto-timer?:false persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl at 5931ef88 initialExpiration=Fri Aug 08 01:08:14 CEST 2014 intervalDuration(in milli sec)=3000 nextExpiration=Fri Aug 08 01:08:17 CEST 2014 timerState=IN_TIMEOUT info=NonPersistentIntervalTimerCLITestCase
8:15,410 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase] (main) waitOnTimeout
01:08:18,446 INFO  [org.jboss.as.test.integration.ejb.timerservice.mgmt.IntervalTimerBean] (EJB default - 8) booom: [id=467f7f53-a6c7-4abe-9d28-63da530eeda6 timedObjectId=ejb-mgmt-timers.ejb-mgmt-timers.IntervalTimerBean auto-timer?:false persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl at 5931ef88 initialExpiration=Fri Aug 08 01:08:14 CEST 2014 intervalDuration(in milli sec)=3000 nextExpiration=Fri Aug 08 01:08:20 CEST 2014 timerState=IN_TIMEOUT info=NonPersistentIntervalTimerCLITestCase

Note the initialExpiration and the nextExpiration. When in Timeout, the nextExpiration is already incremented by intervalDuration. But in failing case it's not. Then, when activate happens nextExpiration is in the past and timer fires directly, which makes the testcase fail.

> NonPersistentIntervalTimerManagementTestCase fails sometimes
> ------------------------------------------------------------
>
>                 Key: WFLY-3630
>                 URL: https://issues.jboss.org/browse/WFLY-3630
>             Project: WildFly
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: Test Suite
>    Affects Versions: 9.0.0.Beta1
>         Environment: Windows 7 SP1, Oracle JDK 1.7.0_60
>            Reporter: Frank Langelage
>            Assignee: Jason Greene
>
> Testcase org.jboss.as.test.integration.ejb.timerservice.mgmt.NonPersistentIntervalTimerManagementTestCase fails sometimes for me when running build with all tests on Windows machine. I never saw this failure on my Solaris box using the same JDK version. And somehow the appearance of the failure seem to be related to the execution time.
> Executing the testsuite during the day does not show me this error. Only in the very late evening / early morning hours the error appeared. (All related to Central European Summer time in my case.)
> I added some debug output an saw, that, in case of failure, after "activateTimer" the timer fires immediately so that there is one timeout too much then. The initial timeout time of the timer is passed, when it's suspended. When activated it seems to make good for the missed timeout sometimes.
> The persistent version of this testcase located in the same package with exactly same logic never fails for me.



--
This message was sent by Atlassian JIRA
(v6.2.6#6264)