Skip to main content

EJB timer - missed expiration

11 replies [Last post]
buddypine
Offline
Joined: 2011-11-17
Points: 0

I've got a simple EJB timer running in GF 3.1.1 that should run a job every week on Sunday at 02:10


@Singleton
public class ScheduledEventServiceBean {

    @Schedule(dayOfWeek = "Sun", hour = "2", minute = "10", persistent = true)
    public void weeklyCommissionAccounting() {
    <span class="Apple-tab-span"> </span>log.info(&quot;Running weekly commission payment accounting {}&quot;, new DateTime());
        ...
    }
...

Sometimes the timer doesn't expire at the specified time and I get no warnings or errors in the logs at all.
(the server is running 24x7 with the app deployed)

However on restart GF detects the missed expiration and will run the job, with an associated log entry:



[#|2011-11-21T11:59:41.211+0000|INFO|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=10;_ThreadName=Thread-2;|Rescheduling missed expiration for periodic timer '1@@1321073364851@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'CREATED' 'PERIODIC' 'Container ID = 86577862673629201' 'Sun Nov 13 02:10:00 GMT 2011' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true # weeklyCommissionAccounting # 0' .  Last timer expiration occurred at Sun Nov 13 02:10:01 GMT 2011|#]

Any ideas why the expiration is not occuring at the correct time? As far as I cen tell the annotation is correct and the fact the GF recognises the event has been missed also indicates this.
Any suggestions for debugging what could be going on here?

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
mvatkina
Offline
Joined: 2005-04-04
Points: 0

This is strange... Can you turn on ejb-container logging to see what is
the next timeout that is being calculated after the expiration? Is it
sepcific to Sundays?

thanks,
-marina

forums@java.net wrote:
> I've got a simple EJB timer running in GF 3.1.1 that should run a job
> every
> week on Sunday at 02:10
>
>

 @Singleton public class ScheduledEventServiceBean {<br />
> @Schedule(dayOfWeek = "Sun", hour = "2", minute = "10", persistent =<br />
> true)<br />
>   public void weeklyCommissionAccounting() {     log.info("Running weekly<br />
> commission payment accounting {}", new DateTime());         ...     }<br />
> ... 
Sometimes the timer doesn't expire at the specified time
> and I
> get no warnings or errors in the logs at all. (the server is running 24x7
> with the app deployed) However on restart GF detects the missed
> expiration
> and will run the job, with an associated log entry:
<br />
> [#|2011-11-21T11:59:41.211+0000|INFO|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=10;_ThreadName=Thread-2;|Rescheduling<br />
><br />
> missed expiration for periodic timer '1@@1321073364851@@server@@domain1'<br />
> 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker'<br />
> 'CREATED' 'PERIODIC' 'Container ID = 86577862673629201' 'Sun Nov 13<br />
> 02:10:00<br />
> GMT 2011' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true #<br />
> weeklyCommissionAccounting # 0' .  Last timer expiration occurred at<br />
> Sun Nov<br />
> 13 02:10:01 GMT 2011|#] 
Any ideas why the expiration is not
> occuring at the correct time? As far as I cen tell the annotation is
> correct
> and the fact the GF recognises the event has been missed also
> indicates this.
> Any suggestions for debugging what could be going on here?
>
>
>
> --
>
> [Message sent by forum member 'buddypine']
>
> View Post: http://forums.java.net/node/866262
>
>

buddypine
Offline
Joined: 2011-11-17
Points: 0

This has not occurred for a couple of months but has just resurfaced again for the first weekly job in February 2012.
The job should have run at 02:10 am on 2012-02-05, I turned on container logging but there are absolutely no entries at this time. The last successful run of this job was the previous week at 2012-01-29T02:10

[#|2012-01-29T02:10:00.003+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=1095;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|Calling ejbTimeout for timer '1@@1327465731971@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 86996792811520017' 'Sun Jan 29 02:10:00 GMT 2012' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true # weeklyCommissionAccounting # 0' |#]

[#|2012-01-29T02:10:00.003+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=1095;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering BaseContainer::preInvoke : EjbInvocation  componentId=leadseeker_/,isLocal=true,isRemote=false,isBusinessInterface=false,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=null,method=public void uk.co.leadseeker.service.ScheduledEventServiceBean.weeklyCommissionAccounting(),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]

[#|2012-01-29T02:10:02.077+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=1095;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=postEjbTimeout;|Setting last expiration  for periodic timer '1@@1327465731971@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 86996792811520017' 'Sun Jan 29 02:10:00 GMT 2012' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true # weeklyCommissionAccounting # 0'  to Sun Jan 29 02:10:02 GMT 2012|#]

[#|2012-01-29T02:10:02.388+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=1095;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving BaseContainer::postInvoke : EjbInvocation  componentId=leadseeker_/,isLocal=true,isRemote=false,isBusinessInterface=false,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=null,method=public void uk.co.leadseeker.service.ScheduledEventServiceBean.weeklyCommissionAccounting(),ejb=uk.co.leadseeker.service.ScheduledEventServiceBean@5ab590a2,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]

[#|2012-01-29T02:10:02.388+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=1095;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling '1@@1327465731971@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 86996792811520017' 'Sun Jan 29 02:10:00 GMT 2012' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true # weeklyCommissionAccounting # 0'  for timeout at Sun Feb 12 02:10:00 GMT 2012|#]

A scheduled weekly job for Monday did however run on 2012-02-06:

[#|2012-02-06T00:00:09.756+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=3166;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving BaseContainer::postInvoke : EjbInvocation  componentId=leadseeker_/,isLocal=true,isRemote=false,isBusinessInterface=false,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=null,method=public void uk.co.leadseeker.service.ScheduledEventServiceBean.weeklyMerchantQuota(),ejb=uk.co.leadseeker.service.ScheduledEventServiceBean@5ab590a2,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]

[#|2012-02-06T00:00:09.757+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=3166;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling '2@@1327465731971@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 86996792811520017' 'Mon Jan 30 00:00:00 GMT 2012' '0' '0 # 0 # 0 # * # * # Mon # * # null # null # null # true # weeklyMerchantQuota # 0'  for timeout at Mon Feb 13 00:00:00 GMT 2012|#]
buddypine
Offline
Joined: 2011-11-17
Points: 0

PS. the 2012-02-05 job did run on a test server running the same app and same Glassfish version.

[#|2012-02-05T02:10:00.586+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=194;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling '1@@1328332243244@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 87053579051532306' 'Sun Feb 05 02:10:00 GMT 2012' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true # weeklyCommissionAccounting # 0'  for timeout at Sun Feb 19 02:10:00 GMT 2012|#]
mvatkina
Offline
Joined: 2005-04-04
Points: 0

May be it's a JDK/OS glitch? How do they differ?

-marina

forums@java.net wrote:
> PS. the 2012-02-05 job did run on a test server running the same app and
> same Glassfish version.
>
> [#|2012-02-05T02:10:00.586+0000|FINE|glassfish3.1.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=194;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling
>
> '1@@1328332243244@@server@@domain1' 'TimedObject =
> ScheduledEventServiceBean'
> 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID =
> 87053579051532306' 'Sun Feb 05 02:10:00 GMT 2012' '0' '0 # 10 # 2 # *
> # * #
> Sun # * # null # null # null # true # weeklyCommissionAccounting # 0' for
> timeout at Sun Feb 19 02:10:00 GMT 2012|#]
>
> --
>
> [Message sent by forum member 'buddypine']
>
> View Post: http://forums.java.net/node/866262
>
>

buddypine
Offline
Joined: 2011-11-17
Points: 0

OS is the same.
Test: JRE name: OpenJDK 64-Bit Server VM Vendor: Sun Microsystems Inc. Version: 20.0-b12
Production: JRE name: OpenJDK 64-Bit Server VM Vendor: Sun Microsystems Inc. Version: 20.0-b11

I'll update the production JDK and see if that helps.

buddypine
Offline
Joined: 2011-11-17
Points: 0

I updated the JDK and the job ran on 2012-02-12 but didn't run on the 19th so it doesn't look like a JDK version issue.

mvatkina
Offline
Joined: 2005-04-04
Points: 0

You have the FINE logging enabled, don't you? Is it that the next
calculated date is wrong or the timeout is not called?

It's really strange that your test machine works correctly (and we had
never seen any problems on our tests)....

forums@java.net wrote:
> I updated the JDK and the job ran on 2012-02-12 but didn't run on the
> 19th
> so it doesn't look like a JDK version issue.
>
>
> --
>
> [Message sent by forum member 'buddypine']
>
> View Post: http://forums.java.net/node/866262
>
>

buddypine
Offline
Joined: 2011-11-17
Points: 0

I do have fine logging enabled. It seems that the timeout is not getting called - on restart after a missed persistent timeout the container always detects this and wil run the job immediately.

I would post all the relevant logs but it's very hard to display/attach them in a sensible manner using this forum so I have tried to condense the pertinent entries:

[#|2012-01-01T02:10:00.900+0000| 'BEING_DELIVERED' for timeout at Sun Jan 15 02:10:00 GMT 2012|#]

[#|2012-01-03T05:56:42.104+0000| 'CREATED'         for timeout at Sun Jan 08 02:10:00 GMT 2012|#]

[#|2012-01-04T06:05:07.334+0000| 'CREATED'         for timeout at Sun Jan 08 02:10:00 GMT 2012|#]

[#|2012-01-08T02:10:00.611+0000| 'BEING_DELIVERED' for timeout at Sun Jan 22 02:10:00 GMT 2012|#]

[#|2012-01-11T05:21:26.866+0000| 'CREATED'         for timeout at Sun Jan 15 02:10:00 GMT 2012|#]

[#|2012-01-13T05:38:13.968+0000| 'CREATED'         for timeout at Sun Jan 15 02:10:00 GMT 2012|#]

[#|2012-01-15T02:10:03.518+0000| 'BEING_DELIVERED' for timeout at Sun Jan 29 02:10:00 GMT 2012|#]

[#|2012-01-25T04:28:52.044+0000| 'CREATED'         for timeout at Sun Jan 29 02:10:00 GMT 2012|#]

[#|2012-01-29T02:10:02.388+0000| 'BEING_DELIVERED' for timeout at Sun Feb 12 02:10:00 GMT 2012|#]

[#|2012-02-08T04:21:41.509+0000| 'CREATED'         for timeout at Wed Feb 08 04:21:42 GMT 2012|#]

[#|2012-02-08T04:21:45.291+0000| 'BEING_DELIVERED' for timeout at Sun Feb 19 02:10:00 GMT 2012|#]

[#|2012-02-08T04:45:55.730+0000| 'CREATED'         for timeout at Sun Feb 12 02:10:00 GMT 2012|#]

[#|2012-02-12T02:10:01.324+0000| 'BEING_DELIVERED' for timeout at Sun Feb 26 02:10:00 GMT 2012|#]

[#|2012-02-22T04:40:11.995+0000| 'CREATED'         for timeout at Wed Feb 22 04:40:12 GMT 2012|#]

[#|2012-02-22T04:40:15.428+0000| 'BEING_DELIVERED' for timeout at Sun Mar 04 02:10:00 GMT 2012|#]
Am I right in saying the 'BEING_DELIVERED' entries are when the timeout is scheduled and the 'CREATED' entries are when the timeout actually occurs?

For the most recent missed timeout on the 19th Feb you can see the timeout was scheduled on 2012-02-08 but did not actually run on the 19th. It did run however at 2012-02-22T04:40 when I restarted Glassfish.

mvatkina wrote:
You have the FINE logging enabled, don't you? Is it that the next calculated date is wrong or the timeout is not called? It's really strange that your test machine works correctly (and we had never seen any problems on our tests).... forums@java.net wrote: > I updated the JDK and the job ran on 2012-02-12 but didn't run on the > 19th > so it doesn't look like a JDK version issue. > > > -- > > [Message sent by forum member 'buddypine'] > > View Post: http://forums.java.net/node/866262 > >

buddypine
Offline
Joined: 2011-11-17
Points: 0

Ok, I'll turn on the logging and report findings on the next run.

I don't know if it is specific to Sundays as that is currently the only day we run weekly jobs, I'll try some testing with reagards to this.

mvatkina
Offline
Joined: 2005-04-04
Points: 0

The next expiration should be reported as: "Scheduling ...timerState ... for timeout at ...".

-marina

buddypine
Offline
Joined: 2011-11-17
Points: 0

I'm still having this problem, when the job ran on 29th July the next expiration was scheduled for 12th August and not the 5th as expected:

[#|2012-07-29T02:10:09.506+0100|FINE|glassfish3.1.2|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=31;_ThreadName=Thread-2;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling '1@@1343190340443@@server@@domain1' 'TimedObject = ScheduledEventServiceBean' 'Application = leadseeker' 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 88027320560058389' 'Sun Jul 29 02:10:00 BST 2012' '0' '0 # 10 # 2 # * # * # Sun # * # null # null # null # true # weeklyCommissionAccounting # 0'  for timeout at Sun Aug 12 02:10:00 BST 2012|#]