1 2 Previous Next 19 Replies Latest reply on Feb 20, 2018 2:27 AM by gjaekel

Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Nov 30, 2017 11:49 AM

I have to run a couple of applications (a server component and a bunch of client services) that uses ejb3 timers. On the clients, this timers are used to trigger a periodical "registration" (with a 5s schedule) at the server component and at the server component, there is a watchdog checking a recent registration (scheduled every 30s).

In principle all works well and "as designed", but after some time (hours or even a couple of minutes) the timers stop working.

I have enabled DEBUG logging for the category "org.jboss.as.ejb3.timer" but the only thing i'm able to get from this is that the regular periodic logging stops after a while for unknown reasons. First, the logging interval expands from 5s to 30s and then, the timer activities vanish at all.

Here some output right after restarting the Wildfly and deploment initialisation:

20171128-134156.301 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-6) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternErschToDdbinternMvbConverter
20171128-134156.307 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-5) Starting timerservice for timedObjectId: picaplus-converter-application.picaplus-converter-adapter-0.0.2.PicaPlusToSyncRepoConverterAdapter
20171128-134156.307 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-8) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToDdbinternStdConverter
20171128-134156.307 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-2) Starting timerservice for timedObjectId: conversion-service.conversion-service-ejb.CheckAvailabilities
20171128-134156.308 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-5) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21OhnedirConverter
20171128-134156.308 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-8) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternLev2ToMarc21OhnedirConverter
20171128-134156.307 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-4) Starting timerservice for timedObjectId: xmetadiss-converter-application.xmetadiss-converter-adapter-1.1.0.XMetaDissToPicaPlusConverterAdapter
20171128-134156.308 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-2) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNpConverter
20171128-134156.309 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-5) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNormConverter
20171128-134156.310 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-8) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToDdbinternGndConverter
20171128-134156.311 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-5) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21PlusConverter
20171128-134156.309 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-6) Starting timerservice for timedObjectId: marc21xml-converter-application.marc21xml-converter-adapter-0.0.2.MarcToMarcXmlConverterAdapter
20171128-134156.312 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-5) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21Converter
20171128-134156.312 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-8) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.PicaMitSbToIsbdTagsConverter
20171128-134156.312 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-2) Starting timerservice for timedObjectId: rdf-converter-application.rdf-converter-adapter-1.0.3.RdfJsonLdConverterAdapter
20171128-134156.312 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-2) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToMarc21OhnedirConverter
20171128-134156.313 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-4) Starting timerservice for timedObjectId: onix-converter-application.onix-converter-adapter-1.1.1.OnixToPicaPlusConverterAdapter
20171128-134156.313 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-6) Starting timerservice for timedObjectId: rdf-converter-application.rdf-converter-adapter-1.0.3.RdfXmlConverterAdapter
20171128-134156.317 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-5) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21PlusOhnedirConverter
20171128-134156.318 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-2) Starting timerservice for timedObjectId: marc21xml-converter-application.marc21xml-converter-adapter-0.0.2.MarcWithoutDirToMarcXmlConverterAdapter
20171128-134156.318 DEBUG [org.jboss.as.ejb3.timer] (MSC service thread 1-4) Starting timerservice for timedObjectId: sch-converter-application.sch-converter-adapter-0.0.2.DdbinternLev2ToMarc21Converter
...

Here some log where the timers are working:

20171128-134200.006 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 5) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=b4b0d7e9-de89-432c-81f1-e4716fdfff41 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternLev2ToMarc21Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@bea9b0b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.007 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 4) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=d5270d84-cba6-4ce0-8995-4afd6906a159 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternLev2Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@29c956ab initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.007 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 3) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=b6881173-ba40-419d-a71c-a33e720d52bb timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21PlusConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@569322bb initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.004 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 1) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=72db8798-cd61-40a3-a434-2270792b72df timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNormConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@13451179 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.011 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 6) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=8895cddd-148b-45e3-af9e-686d22cae9b1 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToPicaMitSBConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@5850296b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.011 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 8) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=23f125b3-c984-442c-b707-78d2c5912a11 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@6de63fc9 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.008 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 4) Scheduling a single action timer [id=d5270d84-cba6-4ce0-8995-4afd6906a159 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternLev2Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@29c956ab initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.992 milliseconds from now
20171128-134200.011 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 6) Scheduling a single action timer [id=8895cddd-148b-45e3-af9e-686d22cae9b1 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToPicaMitSBConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@5850296b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.989 milliseconds from now
20171128-134200.011 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 8) Scheduling a single action timer [id=23f125b3-c984-442c-b707-78d2c5912a11 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@6de63fc9 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.989 milliseconds from now
20171128-134200.011 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 5) Scheduling a single action timer [id=b4b0d7e9-de89-432c-81f1-e4716fdfff41 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternLev2ToMarc21Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@bea9b0b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.989 milliseconds from now
20171128-134200.011 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 1) Scheduling a single action timer [id=72db8798-cd61-40a3-a434-2270792b72df timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNormConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@13451179 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.989 milliseconds from now
20171128-134200.012 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 3) Scheduling a single action timer [id=b6881173-ba40-419d-a71c-a33e720d52bb timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToMarc21PlusConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@569322bb initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.988 milliseconds from now
20171128-134200.012 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 9) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=2a4824d1-1c1a-4caf-957d-fea08deb869e timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToDdbinternStdConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1b941574 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.012 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 9) Scheduling a single action timer [id=2a4824d1-1c1a-4caf-957d-fea08deb869e timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToDdbinternStdConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1b941574 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.988 milliseconds from now
20171128-134200.004 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 2) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=210f0e7b-e28d-4320-8f94-e8084f3ba2c0 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNpConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@6196b78b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.013 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 7) Timer task invoked at: Tue Nov 28 13:42:00 CET 2017 for timer [id=f3175cca-532e-413a-bd38-fa3fc815ba07 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.PicaMitSbToIsbdTagsConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@50c05a63 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:00 CET 2017 timerState=ACTIVE info=null]
20171128-134200.013 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 2) Scheduling a single action timer [id=210f0e7b-e28d-4320-8f94-e8084f3ba2c0 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNpConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@6196b78b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:42:05 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.987 milliseconds from now
...

Here some log where some are already disfunctional ("startin at 0 milliseconds after now"):

20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 8) Timer task invoked at: Tue Nov 28 13:43:15 CET 2017 for timer [id=210f0e7b-e28d-4320-8f94-e8084f3ba2c0 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNpConverter auto-timer?:true persistent?:false timerService=
org.jboss.as.ejb3.timerservice.TimerServiceImpl@6196b78b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:10 CET 2017 timerState=ACTIVE info=null]
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 8) Scheduling a single action timer [id=210f0e7b-e28d-4320-8f94-e8084f3ba2c0 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNpConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@6196b78b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 5) Scheduling a single action timer [id=22327624-ff8f-4c59-98e1-e6c1b487a95c timedObjectId=oaiDc-converter-application.oaiDc-converter-adapter-0.0.2.OaiDcConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@79b577f6 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.013 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 6) Timer task invoked at: Tue Nov 28 13:43:15 CET 2017 for timer [id=eb98fd4a-6642-4af5-b74d-ab3aaa39a16c timedObjectId=xmetadiss-converter-application.xmetadiss-converter-adapter-1.1.0.XMetaDissToPicaPlusConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@9995216 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:10 CET 2017 timerState=ACTIVE info=null]
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 7) Scheduling a single action timer [id=41817df3-fe64-4c23-b0c8-820f5dbc2d83 timedObjectId=picaplus-converter-application.picaplus-converter-adapter-0.0.2.PicaPlusToSyncRepoConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@5b6c100c initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 6) Scheduling a single action timer [id=eb98fd4a-6642-4af5-b74d-ab3aaa39a16c timedObjectId=xmetadiss-converter-application.xmetadiss-converter-adapter-1.1.0.XMetaDissToPicaPlusConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@9995216 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.013 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 10) Timer task invoked at: Tue Nov 28 13:43:15 CET 2017 for timer [id=72db8798-cd61-40a3-a434-2270792b72df timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNormConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@13451179 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:10 CET 2017 timerState=ACTIVE info=null]
20171128-134315.015 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 10) Scheduling a single action timer [id=72db8798-cd61-40a3-a434-2270792b72df timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternNormConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@13451179 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.015 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 9) Scheduling a single action timer [id=caadcd1a-04c3-4a54-944d-4e319814c270 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.Marc21ToDddinternConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@6b44caba initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 4) Scheduling a single action timer [id=20395094-15a8-4dd9-8558-d1377b798aff timedObjectId=picaplus-converter-application.picaplus-converter-adapter-0.0.2.PicaPlusToPicaXMLConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@2aa8bfaf initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 3) Scheduling a single action timer [id=b4b0d7e9-de89-432c-81f1-e4716fdfff41 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternLev2ToMarc21Converter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@bea9b0b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=IN_TIMEOUT info=null] starting at 0 milliseconds from now
20171128-134315.014 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 1) Timer task invoked at: Tue Nov 28 13:43:15 CET 2017 for timer [id=ed1ed9d0-cb9c-4af5-b4dd-422ce9430ce0 timedObjectId=mods-converter-application.mods-converter-adapter-1.0.0.ModsConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1f682bf3 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=ACTIVE info=null]
20171128-134315.016 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 1) Scheduling a single action timer [id=ed1ed9d0-cb9c-4af5-b4dd-422ce9430ce0 timedObjectId=mods-converter-application.mods-converter-adapter-1.0.0.ModsConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1f682bf3 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:20 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.984 milliseconds from now
20171128-134315.016 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 6) Timer task invoked at: Tue Nov 28 13:43:15 CET 2017 for timer [id=bf6f955f-f59c-4044-8f3a-be6de99dcb97 timedObjectId=rdf-converter-application.rdf-converter-adapter-1.0.3.RdfJsonLdConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1ef949e8 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=ACTIVE info=null]
20171128-134315.016 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 5) Timer task invoked at: Tue Nov 28 13:43:15 CET 2017 for timer [id=8895cddd-148b-45e3-af9e-686d22cae9b1 timedObjectId=sch-converter-application.sch-converter-adapter-0.0.2.DdbinternToPicaMitSBConverter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@5850296b initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:15 CET 2017 timerState=ACTIVE info=null]
20171128-134315.016 DEBUG [org.jboss.as.ejb3.timer] (EJB default - 6) Scheduling a single action timer [id=bf6f955f-f59c-4044-8f3a-be6de99dcb97 timedObjectId=rdf-converter-application.rdf-converter-adapter-1.0.3.RdfJsonLdConverterAdapter auto-timer?:true persistent?:false timerService=org.jboss.as.ejb3.timerservice.TimerServiceImpl@1ef949e8 initialExpiration=null intervalDuration(in milli sec)=0 nextExpiration=Tue Nov 28 13:43:20 CET 2017 timerState=IN_TIMEOUT info=null] starting at 4.984 milliseconds from now

Somewhat later, there's only logging at seconds 00 and 30 of a minute. And in the end, all timer logging disappears.

This issue only happen in the production environment with real workload on the applications.
This bundle of applications is deployed on two indepentend, unclustered and just load/failover-balanced instances Wildfly. The issue occurs on both, but unrelated in time.
It don't happen on indentical configured servers on the approval and on the test stage.

Please ask for any further information you'll need!

1. Re: Wildfly-10.1: EJB3 Timer stop working after a while

jaikiran Nov 30, 2017 11:31 PM (in response to gjaekel)

How are the timers created? Using @Schedule or programatic API? Please post that relevant snippets.

Which exact version of Java and which vendor? Please post the output of "java -version" from the system(s) where you observe this issue.

On the system(s) where this issue is observed, what timezone is applicable and is that system part of any DST (daylight saving time) changes?

Finally, WildFly 11.0.0.Final has been released some weeks back. If possible, please upgrade to that version and see if it's reproducible there. Using the latest released version will make it easier to investigate and fix any potential issue in the server code itself.
Actions

2. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 5, 2017 9:41 AM (in response to jaikiran)

Dear Jaikiran,

thank you for giving your time. As said, this only happens in the production environment, but the developers and testers said that they are not able to reproduce it in the nearly identical approval or test environment, yet.

The Timers seems to be created by annotations. I found two one that seems to correspond to the the 30s timer and the 5s timers:

@Schedule(second = "*/30", minute = "*", hour = "*", persistent = false)
    public void checkAvailabilities() {
        LOGGER.debug("Checking availability of registered ConverterServices...");
        try {
            final Collection remoteConverters = this.remoteConverterRepository.findAll();

            for (final RemoteConverter remoteConverter : remoteConverters) {
                if (isOlderThanInavailabilityDeadline(remoteConverter)) {
                    if (isOlderThanRemoveFromRegisterDeadline(remoteConverter)) {
                        this.remoteConverterRepository.remove(remoteConverter);
                        LOGGER.info("Removed inactive ConversionService=\"{}\".", remoteConverter);
                    } else if (remoteConverter.isAvailable()) {
                        remoteConverter.setAvailability(Availability.UNAVAILABLE);
                        LOGGER.info("Set ConversionService=\"{}\" as inactive.", remoteConverter);
                    }
                }
            }
        } catch (final Exception e) {
            LOGGER.warn("Error while checking availability of registered ConverterServices.", e);
        }
        LOGGER.debug("Finished availability check of registered ConverterServices.");
    }

@Schedule(second = "*/5", minute = "*", hour = "*", persistent = false)
    protected void register() {
          registrationHelper.register(sourceFormat, targetFormat, getMyJndiAddress());
    }

The JVM used is recent version:

# java -version
java version "1.8.0_152"
Java(TM) SE Runtime Environment (build 1.8.0_152-b16)
Java HotSpot(TM) 64-Bit Server VM (build 25.152-b16, mixed mode)

Timezone is Germany, i.e. GMT+1 at the moment.

It's not possible to upgrade the production environment to WF11 ad-hoc because neither the developers department nor the business department have approved it, yet.

It happens again just at yesterday and here the timer get disfunctional right during/after startup of the Wildfly. I have append the complete Wildfly log of this startup.Also, I triggered to write down a treaddump (by SIGQUIT) this morning before restarting the server. In addition, I pull a complete heapdump. It's much to big to append here, but you may request for it.

Please ask any more question you like!

wildfly.log.prodfly2.20171130-171935.bz2 13.4 KB
wildfly.threaddump.prodfly2.20171201-093245.bz2 22.9 KB
CheckAvailabilities.java 3.4 KB
AbstractConverterAdapter.java 2.7 KB

3. Re: Wildfly-10.1: EJB3 Timer stop working after a while

jaikiran Dec 6, 2017 6:34 AM (in response to gjaekel)

Based on the logs and the thread dumps, I couldn't find anything that suggests what the cause of this is. It's either the timer is cancelled (which is unlikely given that it's a @Schedule one) or the next expiration of the timer is considered null (or too far into the future). The latter is possible, but I can't really say if it's a bug or some kind of timezone issue, especially given that this is WildFly 10.

Timezone is Germany, i.e. GMT+1 at the moment.
Is that the same on the systems where this is reproducible and on the systems where this isn't reproducible?

The other factor to consider is whether the executor service backing the timerservice is causing the timer invocations to be backlogged due to the number of timers being scheduled. The timer service thread pool is configured in the "ejb3" subsystem (search for the timer-service element in the right domain/standalone configuration file of your setup and then see the thread-pool characteristic of the thread pool that's configured using the thread-pool-name attribute, of that element). See if that thread pool meets your needs or if you need to tune it.
Actions
4. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 6, 2017 6:35 PM (in response to jaikiran)
Dear Jaikiran,
thank you for the analysis of the dumps.

Timezone and even system time is exactly the same because the Wildflys are running inside seperate LXC containers spread on different blades as LXC host synchronized by NTPd on the same bladecenter.
Stucked timers have a negative nextSchedule. I'm able to see this by help of the MBean interface using JVisualVM.

I'm not at work at the moment (it's about midnight local time) but i try to take a look at the thread pools this day.
Actions
5. Re: Wildfly-10.1: EJB3 Timer stop working after a while

jaikiran Dec 6, 2017 11:15 PM (in response to gjaekel)
gjaekel wrote:

Stucked timers have a negative nextSchedule. I'm able to see this by help of the MBean interface using JVisualVM.

In that case, please also attach the data/screenshot(s) of the relevant MBeans. That might give us some hint.
Actions
6. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 7, 2017 10:16 AM (in response to jaikiran)
Dear Jaikiran,
i'm sorry:
I was not able to find a tool to access the MBean interface via JMX on commandline, yet. I try out jmxterm, but it's not working. Do you know a usable solution?
Using the wildfly-cli, i'm not able to access all MBeans but just a very limited subset.
For this, I just was able to do a sceenshot of the data. You find two; the first shows a currently stucked timer on the first and the second the same but working on the other of two hosts/wildflys. Note, that the wildfly instance are not clustered but just load/failover-balanced by the frontend reverse proxy (Apache httpd+mod_jk)
There about 50 of other, technical identical timers on other EJBs with different business logics. As i can see from the code, the attribute timeRemaing is calculated as "nextSchedule-now()". And because the Schedule is late, it's negative. Inside the timer code, this negative values are clamped to zeor, therefore the DEBUG log prints the next schedule as 0 millis ahead.
Actions
7. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 7, 2017 10:19 AM (in response to jaikiran)

Dear Jaikiran,,

the configuration of the timer service is default.

<timer-service thread-pool-name="default" default-data-store="default-file-store">
    <data-stores>
        <file-data-store name="default-file-store" path="timer-service-data" relative-to="jboss.server.data.dir"/>
    </data-stores>
</timer-service>

I don't know how to know if this meets my needs because i don't know about the needs. I expect that there are as many threads created as timeout callbacks have to fire and that the outstanding callbacks are queued otherwise.

Howto read out (via cli or MBean) the occupation of the thread pool? You said, you had taken a look at the thread dump and did not found "unexpected things". If the pools is exhausted, you have to find a (higher) number of corresponding threads, right?
Actions
8. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 8, 2017 3:05 AM (in response to jaikiran)

Dear Jaikiran,

I still did not found a working tool to interact with MBeans via JMX on Linux Commandline. I found the corresponding MBean for the used threadpool. In the "stucked" case, there's no further activity. In the working case, the usage counter steps every 5s as expected. But the active thread count is zero in both cases.
Actions
9. Re: Wildfly-10.1: EJB3 Timer stop working after a while

jaikiran Dec 8, 2017 7:08 AM (in response to gjaekel)

gjaekel wrote:

Dear Jaikiran,

I still did not found a working tool to interact with MBeans via JMX on Linux Commandline.
The screenshots you have attached so far are good enough for now.

In general, the negative value for the timeRemaining is OK since as you note, in such cases it's inferred as 0 and the schedule is set to immediately fire. That's all fine. The part that seems to have gone wrong for some reason is that it appears that at some point during attempting to schedule a next run at T1 something went wrong and it never got scheduled. When that happened, the timer task never got a chance to schedule a subsequent timer at T2 (since that logic of scheduling "next" timer happens when T1 gets invoked, for auto timers). This is all theory based on what I think is happening and the code at hand, but I haven't yet had a chance to fully look into this.

Are any transactions involved in your timeout method(s)? Did any of the transaction fail/rollback on some occasion for these timers (do the logs indicate anything)? Do you even need any transaction semantics on those timeout methods?
Actions
10. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 11, 2017 9:35 AM (in response to jaikiran)

Dear Jaikiran,

you think that the callback at T1 never come back or that something with the scheduling goes wrong?
Are any transactions involved in your timeout method(s)? Did any of the transaction fail/rollback on some occasion for these timers (do the logs indicate anything)? Do you even need any transaction semantics on those timeout methods?
I can't see any related in the logs. I send you the log of a complete failed startup.

I'm *not* the developer of this code, i'm trying to keep the deployments running at the "operations department". I just know that the purpose of this mechanims is to register business cases of application modules (EJBs deployed inside EARs) to an main application (WAR/EJB inside an EAR) in a periodical way: The module have to send an "keep alive" registration and the main module will periodically check if this registration is fresh.

I may send you the source code if you like. Tell me if you want, because then have to ask for it first.

Guido
Actions
11. Re: Wildfly-10.1: EJB3 Timer stop working after a while

jaikiran Dec 15, 2017 8:42 AM (in response to gjaekel)

The fact that the timer stops triggering the timeouts does indicate a bug. So I recommend that you file a WildFly JIRA here - JBoss Issue Tracker . Having said that, I think since you are on WildFly 10, unless there's a way to reproduce this using some sample application, you might be asked to try this out on WildFly 11 to try and reproduce it. But it's better to file the JIRA. I haven't had a chance to look much into the code and probably won't have in the next few weeks. Someone else might have a chance to look more into this.
Actions
12. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Dec 15, 2017 9:09 AM (in response to jaikiran)

Dear Jaikiran,

thank you again for your time. Mid next week i'm going to holidays, too until 2nd week of Jan. I will try to run it on WF11 but as said this problem don't occur neighter on approval nor testing stage, therefor the problem is connected to "real" workload. But I can't put WF11 in production without agreements.

I found a tool called goreplay that might be able to "double" the requests and therefore to mirror it to a WF11 with this application. This might be realistic, because the business case is a "stateless" data conversion without any persistens and i may route the result of the mirror to "/dev/null".

I'll try to file the problem on the Issue tracker if i get the time the last days before XMas next week.

with greetings

Guido
Actions

13. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Jan 15, 2018 3:52 AM (in response to jaikiran)

I just found that the "default" thread pool (which the ejb3 timer service is using) is expanded to the maximum, but there's nothing active, queued or rejected, too:

[standalone@localhost:9990 /] ls /subsystem=ejb3/thread-pool=default
active-count=0                                            largest-thread-count=10                                   rejected-count=0                                          
completed-task-count=623713                               max-threads=10                                            task-count=623713                                         
current-thread-count=10                                   name=default                                              thread-factory=undefined                                  
keepalive-time={"time" => 100L,"unit" => "MILLISECONDS"}  queue-size=0

This holds for both instances. Nevertheless, I'll enlarge this thread pool because there's a release of one of the applications in discussion and because the "timer thing" isn't working I have to restart the Wildflies for deployment.

14. Re: Wildfly-10.1: EJB3 Timer stop working after a while

gjaekel Jan 22, 2018 4:28 AM (in response to gjaekel)

On last Friday we need a restart of the Wildfly farm. On one of the both Wildfly with the application in discussion, the "Timers" don't start at all, again. As written, the derault thread pool was expanded to 32 theads (from the default of 10).

Here the current values of the thread pool as shown in the cli:

[standalone@localhost:9990 /] ls /subsystem=ejb3/thread-pool=default
active-count=0                                            largest-thread-count=1                                    rejected-count=0                                          
completed-task-count=1                                    max-threads=32                                            task-count=1                                              
current-thread-count=1                                    name=default                                              thread-factory=undefined                                  
keepalive-time={"time" => 100L,"unit" => "MILLISECONDS"}  queue-size=0

1 2 Previous Next

Go to original post