Loading...

Type: Bug
Resolution: Unresolved
Priority: Major
Fix Version/s: None
Affects Version/s: 8.0 Update 1.1
Component/s: Clustering, EJB
Labels:
None

Blocked:
False
Blocked Reason:
None
Ready:
False
CDW devel_ack:
CDW docs_ack:
CDW pm_ack:
CDW qa_ack:
CDW release:
Target Release:

8.0.z.GA
Intelligence Requested:
Market:

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

Environment:

JBoss EAP 8.0 Update 1.1
server running HA profile (with default Infinispan based EJB timer configuration)

If there's a timer scheduled to run every 10 seconds and the server is going to be suspended for a minute, the timer is executed 6 times when the server is being resumed on JBoss EAP 8.0 Update 1.1, see:

[Server:ha-node-1] 11:19:54,364 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:19:54,364 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:19:54,378 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464

[Server:ha-node-1] 11:20:01,129 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 75) WFLYSRV0272: Suspending server
[Server:ha-node-1] 11:20:01,129 INFO  [org.jboss.as.ejb3] (ServerService Thread Pool -- 75) WFLYEJB0493: Jakarta Enterprise Beans subsystem suspension complete

[Server:ha-node-1] 11:21:02,240 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 75) WFLYSRV0212: Resuming server
[Server:ha-node-1] 11:21:02,241 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:02,241 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:02,248 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464
[Server:ha-node-1] 11:21:02,248 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:02,248 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:02,256 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464
[Server:ha-node-1] 11:21:02,257 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:02,257 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:02,266 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464
[Server:ha-node-1] 11:21:02,267 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:02,267 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:02,277 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464
[Server:ha-node-1] 11:21:02,277 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:02,277 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:02,285 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464
[Server:ha-node-1] 11:21:02,285 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:02,285 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:02,292 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464

[Server:ha-node-1] 11:21:04,364 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 45c85457-3904-4776-b8a4-20cd080ceab5, info: Timer created at 2024-05-28T11:07:42.363464, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:21:04,364 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:07:42.363464 Persistent: true
[Server:ha-node-1] 11:21:04,375 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:07:42.363464

Note: When running the same scenario on wildfly-32.0.0.Final, the missed timer expirations are not resulting in any execution after resuming the server, it just continues with it's regular intervall, see:

[Server:ha-node-1] 11:24:24,506 INFO  [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly Full 32.0.0.Final (WildFly Core 24.0.0.Final) started in 11916ms - Started 585 of 837 services (529 services are lazy, passive or on-demand) 

[Server:ha-node-1] 11:24:25,777 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 6b4047e3-6ed8-4ad1-9926-f92c95511e30, info: Timer created at 2024-05-28T11:24:23.772856, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:24:25,778 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:24:23.772856 Persistent: true
[Server:ha-node-1] 11:24:25,803 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:24:23.772856

[Server:ha-node-1] 11:24:30,004 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 76) WFLYSRV0272: Suspending server
[Server:ha-node-1] 11:24:30,006 INFO  [org.jboss.as.ejb3] (ServerService Thread Pool -- 76) WFLYEJB0493: Jakarta Enterprise Beans subsystem suspension complete

[Server:ha-node-1] 11:25:31,372 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 76) WFLYSRV0212: Resuming server

[Server:ha-node-1] 11:25:35,773 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) Timer: id: 6b4047e3-6ed8-4ad1-9926-f92c95511e30, info: Timer created at 2024-05-28T11:24:23.772856, class: class org.jboss.as.ejb3.timerservice.distributable.DistributableTimer
[Server:ha-node-1] 11:25:35,774 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) START: Timer created at 2024-05-28T11:24:23.772856 Persistent: true
[Server:ha-node-1] 11:25:35,793 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 1) END: Timer created at 2024-05-28T11:24:23.772856

Both behaviors are wrong!

When resuming the server the last missed expiration should be executed, like it is done with the database-data-store based configuration, see:

[Server:ha-node-1] 11:28:06,625 INFO  [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: JBoss EAP 8.0 Update 1.1 (WildFly Core 21.0.5.Final-redhat-00001) started in 9939ms - Started 560 of 824 services (507 services are lazy, passive or on-demand) 

[Server:ha-node-1] 11:28:07,626 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) Timer: id: [id=54f46547-2e28-4e8b-b70b-ff0361434468 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=Tue May 28 11:28:07 CEST 2024 initialExpiration=Tue May 28 11:28:07 CEST 2024 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 11:28:17 CEST 2024 timerState=IN_TIMEOUT info=Timer created at 2024-05-28T11:28:05.604408], info: Timer created at 2024-05-28T11:28:05.604408, class: class org.jboss.as.ejb3.timerservice.TimerImpl
[Server:ha-node-1] 11:28:07,627 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) START: Timer created at 2024-05-28T11:28:05.604408 Persistent: true
[Server:ha-node-1] 11:28:07,627 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) END: Timer created at 2024-05-28T11:28:05.604408

[Server:ha-node-1] 11:28:14,485 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 76) WFLYSRV0272: Suspending server
[Server:ha-node-1] 11:28:14,486 INFO  [org.jboss.as.ejb3] (ServerService Thread Pool -- 76) WFLYEJB0493: Jakarta Enterprise Beans subsystem suspension complete

[Server:ha-node-1] 11:29:15,332 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 76) WFLYSRV0212: Resuming server
[Server:ha-node-1] 11:29:15,358 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) Timer: id: [id=54f46547-2e28-4e8b-b70b-ff0361434468 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=Tue May 28 11:28:07 CEST 2024 initialExpiration=Tue May 28 11:28:07 CEST 2024 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 11:29:17 CEST 2024 timerState=IN_TIMEOUT info=Timer created at 2024-05-28T11:28:05.604408], info: Timer created at 2024-05-28T11:28:05.604408, class: class org.jboss.as.ejb3.timerservice.TimerImpl
[Server:ha-node-1] 11:29:15,358 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) START: Timer created at 2024-05-28T11:28:05.604408 Persistent: true
[Server:ha-node-1] 11:29:15,358 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) END: Timer created at 2024-05-28T11:28:05.604408
[Server:ha-node-1] 11:29:17,634 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) Timer: id: [id=54f46547-2e28-4e8b-b70b-ff0361434468 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=Tue May 28 11:28:07 CEST 2024 initialExpiration=Tue May 28 11:28:07 CEST 2024 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 11:29:27 CEST 2024 timerState=IN_TIMEOUT info=Timer created at 2024-05-28T11:28:05.604408], info: Timer created at 2024-05-28T11:28:05.604408, class: class org.jboss.as.ejb3.timerservice.TimerImpl
[Server:ha-node-1] 11:29:17,634 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) START: Timer created at 2024-05-28T11:28:05.604408 Persistent: true
[Server:ha-node-1] 11:29:17,635 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) END: Timer created at 2024-05-28T11:28:05.604408

is related to

WFLY-19271 Distributed timer service drops timeout events if server is suspended

Resolved

split to

WFLY-19419 Distributed timer service should consolidate timeouts that would execute in the past

Resolved

Details

Description

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates