10 Replies Latest reply on Dec 11, 2017 9:35 AM by Guido Jäkel

    Wildfly-10.1: EJB3 Timer stop working after a while

    Guido Jäkel Newbie

      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 pai Master

          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.

          • 2. Re: Wildfly-10.1: EJB3 Timer stop working after a while
            Guido Jäkel Newbie

            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!

            • 3. Re: Wildfly-10.1: EJB3 Timer stop working after a while
              jaikiran pai Master

              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.

              • 4. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                Guido Jäkel Newbie

                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.

                • 5. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                  jaikiran pai Master

                  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.

                  • 6. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                    Guido Jäkel Newbie

                    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)

                    stucked timer on host prodfly2woring timer on host prodfly3

                    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.

                    • 7. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                      Guido Jäkel Newbie

                      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?

                      • 8. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                        Guido Jäkel Newbie

                        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.

                         

                        ejb3 default threadpool with working timers (ProdFly3)

                        • 9. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                          jaikiran pai Master

                          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?

                          • 10. Re: Wildfly-10.1: EJB3 Timer stop working after a while
                            Guido Jäkel Newbie

                            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