Skip to main content

Non-persistent Singleton timers in a clustered environment using GF3.1

Please note these java.net forums are being decommissioned and use the new and improved forums at https://community.oracle.com/community/java.
7 replies [Last post]
whshub
Offline
Joined: 2010-02-27

I'm trying to use non-persistent timers to fire singleton actions (for
refreshing local cache) in a clustered environment. The same code works
fine if I run it in a non-clustered environment.

I've tried both TimerService.createIntervalTimer and @Schedule annotation
and neither seems to work correctly.

When I monitor the ejb-timer-service-app I see that the timer gets created
but then it disappears after the first expiration. I don't see any errors
in the logs.

//works fine, fires every third minute for one instance in cluster
@Schedule(minute="*/3", hour="*", dayOfMonth="*", month="*", year="*")
public void startWork(Timer t)

// Never fired. Upon deploy, all nodes in cluster show an active
non-persistent timer (via EJB timer web app). Timer disappears after what
appears to be first expiration.
@Schedule(minute="*/3", hour="*", dayOfMonth="*", month="*", year="*",
persistent=false) public void startWork(Timer t)

What is the expected functionality in a clustered singleton environment? As
described above, I know that persistent timers work fine (and are
constrained to a single instance across the cluster as expected).

Which logger would give me more information about what is happening?

Thanks,
Jacques

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

May be there is something going on in your setup? An interceptor of any
kind? The timer behavior shouldn't change during the run. Non-persistent
timers are getting recreated after each restart (on each instance - vs.
persistent timers that will be executed only on 1 instance in a cluster).

-marina

Jacques wrote:
> I'm trying to use non-persistent timers to fire singleton actions (for
> refreshing local cache) in a clustered environment. The same code
> works fine if I run it in a non-clustered environment.
>
> I've tried both TimerService.createIntervalTimer and @Schedule
> annotation and neither seems to work correctly.
>
> When I monitor the ejb-timer-service-app I see that the timer gets
> created but then it disappears after the first expiration. I don't
> see any errors in the logs.
>
> //works fine, fires every third minute for one instance in cluster
> @Schedule(minute="*/3", hour="*", dayOfMonth="*", month="*", year="*")
> public void startWork(Timer t)
>
> // Never fired. Upon deploy, all nodes in cluster show an active
> non-persistent timer (via EJB timer web app). Timer disappears after
> what appears to be first expiration.
> @Schedule(minute="*/3", hour="*", dayOfMonth="*", month="*", year="*",
> persistent=false) public void startWork(Timer t)
>
>
> What is the expected functionality in a clustered singleton
> environment? As described above, I know that persistent timers work
> fine (and are constrained to a single instance across the cluster as
> expected).
>
> Which logger would give me more information about what is happening?
>
> Thanks,
> Jacques

cf126330
Offline
Joined: 2005-03-29

Can you try with javax.enterprise.system.container.ejb.level=FINE?

whshub
Offline
Joined: 2010-02-27

I re-ran with the updated logging. I see a log event that says the timer
was cancelled by another instance. How would that happen?

I tried to attach appropriate log lines below. First part is during
deployment. Second part is timer expiration.

thanks for any help,
Jacques

====DEPLOY========
[#|2011-07-18T16:29:09.143-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
BaseContainer::postInvoke : EjbInvocation
componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
com.sun.ejb.containers.TimerLocal,method=public abstract java.util.Set
com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=com.sun.ejb.containers.TimerBean@851bfe0
,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
[#|2011-07-18T16:29:09.144-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=_restoreTimers;|DONE
EJBTimerService.restoreTimers()|#]
[#|2011-07-18T16:29:11.968-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=createTimer;|@@@
Created timer [1@@1311031751968@@h002-batch@@h002-batch] with the first
expiration set to: Mon Jul 18 16:29:41 PDT 2011|#]
[#|2011-07-18T16:29:11.970-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.RuntimeTimerState;MethodName=;|RuntimeTimerState
1@@1311031751968@@h002-batch@@h002-batch created|#]
[#|2011-07-18T16:29:11.971-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerCache;MethodName=addTimer;|Adding
timer '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject =
DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED' 'PERIODIC'
'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000'
|#]
[#|2011-07-18T16:29:11.999-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerSynch;MethodName=afterCompletion;|TimerSynch::afterCompletion.
timer state = TIMER_ACTIVE , timer id =
1@@1311031751968@@h002-batch@@h002-batch
, JTA TX status = TX_STATUS_COMMITTED , timeout = Mon Jul 18 16:29:41 PDT
2011|#]
[#|2011-07-18T16:29:12.000-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling
'1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject =
DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED' 'PERIODIC'
'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000'
for timeout at Mon Jul 18 16:29:41 PDT 2011|#]
[#|2011-07-18T16:29:12.011-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering
BaseContainer::preInvoke : EjbInvocation
componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
com.sun.ejb.containers.TimerLocal,method=public abstract java.util.Set
com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
[#|2011-07-18T16:29:12.011-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=124;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
Access Control Decision Result: true EJBMethodPermission (Name) = TimerBean
(Action) = findActiveTimersOwnedByThisServerByContainer,Local,long (Caller)
= null|#]
[#|2011-07-18T16:29:12.013-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
BaseContainer::postInvoke : EjbInvocation
componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
com.sun.ejb.containers.TimerLocal,method=public abstract java.util.Set
com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=com.sun.ejb.containers.TimerBean@851bfe0
,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
[#|2011-07-18T16:29:12.013-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=_restoreTimers;|DONE
EJBTimerService.restoreTimers()|#]

======EXPIRATION======
[#|2011-07-18T16:29:41.945-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=144;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=taskExpired;|Adding
work pool task for timer 1@@1311031751968@@h002-batch@@h002-batch|#]
[#|2011-07-18T16:29:41.946-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|EJBTimerService.deliverTimeout():
work thread is processing work for timerId = 1@@1311031751968@@h002-batch@
@h002-batch|#]
[#|2011-07-18T16:29:41.947-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|Calling
ejbTimeout for timer '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject
= DatabaseIntermdiaryImpl' 'Application = batch' 'BEING_DELIVERED'
'PERIODIC' 'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011'
'60000' |#]
[#|2011-07-18T16:29:41.947-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|For
Timer :1@@1311031751968@@h002-batch@@h002-batch: check the database to
ensure that the timer is still valid, before delivering the ejbTimeout
call|#]
[#|2011-07-18T16:29:41.948-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering
BaseContainer::preInvoke : EjbInvocation
componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
com.sun.ejb.containers.TimerLocal,method=public abstract
com.sun.ejb.containers.TimerState
com.sun.ejb.containers.TimerLocal.findTimer(com.sun.ejb.containers.TimerPrimaryKey),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
[#|2011-07-18T16:29:41.948-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
permission initialized in InvocationInfo: EJBMethodPermission (Name) =
TimerBean (Action) =
findTimer,Local,com.sun.ejb.containers.TimerPrimaryKey|#]
[#|2011-07-18T16:29:41.949-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
Access Control Decision Result: true EJBMethodPermission (Name) = TimerBean
(Action) = findTimer,Local,com.sun.ejb.containers.TimerPrimaryKey (Caller) =
null|#]
[#|2011-07-18T16:29:41.950-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=resetPolicyContext;|JACC:
Changing Policy Context ID: oldV = null newV =
ejb-timer-service-app/ejb-timer-service-app_internal|#]
[#|2011-07-18T16:29:41.958-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
BaseContainer::postInvoke : EjbInvocation
componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
com.sun.ejb.containers.TimerLocal,method=public abstract
com.sun.ejb.containers.TimerState
com.sun.ejb.containers.TimerLocal.findTimer(com.sun.ejb.containers.TimerPrimaryKey),ejb=com.sun.ejb.containers.TimerBean@851bfe0
,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
[#|2011-07-18T16:29:41.959-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=getValidTimerFromDB;|Timer
:1@@1311031751968@@h002-batch@@h002-batch: has been cancelled by another
server instance. Expunging the timer from h002-batch's cache.|#]
[#|2011-07-18T16:29:41.959-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerCache;MethodName=removeTimer;|Removing
timer 1@@1311031751968@@h002-batch@@h002-batch|#]

On Mon, Jul 18, 2011 at 10:43 AM, wrote:

> Can you try with javax.enterprise.system.**container.ejb.level=FINE?
>
>
> --
>
> [Message sent by forum member 'cf126330']
>
> View Post: http://forums.java.net/node/**823173
>
>
>

mvatkina
Offline
Joined: 2005-04-04

It's a bug (strangely it works in our tests). Try setting System
property "com.sun.ejb.timer.ReadDBBeforeTimeout=false".

thanks,
-marina

Jacques wrote:
> I re-ran with the updated logging. I see a log event that says the
> timer was cancelled by another instance. How would that happen?
>
> I tried to attach appropriate log lines below. First part is during
> deployment. Second part is timer expiration.
>
> thanks for any help,
> Jacques
>
> ====DEPLOY========
> [#|2011-07-18T16:29:09.143-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
> BaseContainer::postInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract java.util.Set
> com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=com.sun.ejb.containers.TimerBean@851bfe0,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:09.144-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=_restoreTimers;|DONE
> EJBTimerService.restoreTimers()|#]
> [#|2011-07-18T16:29:11.968-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=createTimer;|@@@
> Created timer [1@@1311031751968@@h002-batch@@h002-batch] with the
> first expiration set to: Mon Jul 18 16:29:41 PDT 2011|#]
> [#|2011-07-18T16:29:11.970-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.RuntimeTimerState;MethodName=;|RuntimeTimerState
> 1@@1311031751968@@h002-batch@@h002-batch created|#]
> [#|2011-07-18T16:29:11.971-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerCache;MethodName=addTimer;|Adding
> timer '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject =
> DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED' 'PERIODIC'
> 'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011'
> '60000' |#]
> [#|2011-07-18T16:29:11.999-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerSynch;MethodName=afterCompletion;|TimerSynch::afterCompletion.
> timer state = TIMER_ACTIVE , timer id =
> 1@@1311031751968@@h002-batch@@h002-batch , JTA TX status =
> TX_STATUS_COMMITTED , timeout = Mon Jul 18 16:29:41 PDT 2011|#]
> [#|2011-07-18T16:29:12.000-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling
> '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject =
> DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED' 'PERIODIC'
> 'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011'
> '60000' for timeout at Mon Jul 18 16:29:41 PDT 2011|#]
> [#|2011-07-18T16:29:12.011-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering
> BaseContainer::preInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract java.util.Set
> com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:12.011-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=124;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
> Access Control Decision Result: true EJBMethodPermission (Name) =
> TimerBean (Action) =
> findActiveTimersOwnedByThisServerByContainer,Local,long (Caller) = null|#]
> [#|2011-07-18T16:29:12.013-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
> BaseContainer::postInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract java.util.Set
> com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=com.sun.ejb.containers.TimerBean@851bfe0,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:12.013-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=_restoreTimers;|DONE
> EJBTimerService.restoreTimers()|#]
>
>
>
>
> ======EXPIRATION======
> [#|2011-07-18T16:29:41.945-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=144;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=taskExpired;|Adding
> work pool task for timer 1@@1311031751968@@h002-batch@@h002-batch|#]
> [#|2011-07-18T16:29:41.946-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|EJBTimerService.deliverTimeout():
> work thread is processing work for timerId =
> 1@@1311031751968@@h002-batch@@h002-batch|#]
> [#|2011-07-18T16:29:41.947-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|Calling
> ejbTimeout for timer '1@@1311031751968@@h002-batch@@h002-batch'
> 'TimedObject = DatabaseIntermdiaryImpl' 'Application = batch'
> 'BEING_DELIVERED' 'PERIODIC' 'Container ID = 85917732333944859' 'Mon
> Jul 18 16:29:41 PDT 2011' '60000' |#]
> [#|2011-07-18T16:29:41.947-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|For
> Timer :1@@1311031751968@@h002-batch@@h002-batch: check the database to
> ensure that the timer is still valid, before delivering the
> ejbTimeout call|#]
> [#|2011-07-18T16:29:41.948-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering
> BaseContainer::preInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> com.sun.ejb.containers.TimerState
> com.sun.ejb.containers.TimerLocal.findTimer(com.sun.ejb.containers.TimerPrimaryKey),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:41.948-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
> permission initialized in InvocationInfo: EJBMethodPermission (Name) =
> TimerBean (Action) =
> findTimer,Local,com.sun.ejb.containers.TimerPrimaryKey|#]
> [#|2011-07-18T16:29:41.949-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
> Access Control Decision Result: true EJBMethodPermission (Name) =
> TimerBean (Action) =
> findTimer,Local,com.sun.ejb.containers.TimerPrimaryKey (Caller) = null|#]
> [#|2011-07-18T16:29:41.950-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=resetPolicyContext;|JACC:
> Changing Policy Context ID: oldV = null newV =
> ejb-timer-service-app/ejb-timer-service-app_internal|#]
> [#|2011-07-18T16:29:41.958-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
> BaseContainer::postInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> com.sun.ejb.containers.TimerState
> com.sun.ejb.containers.TimerLocal.findTimer(com.sun.ejb.containers.TimerPrimaryKey),ejb=com.sun.ejb.containers.TimerBean@851bfe0,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:41.959-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=getValidTimerFromDB;|Timer
> :1@@1311031751968@@h002-batch@@h002-batch: has been cancelled by
> another server instance. Expunging the timer from h002-batch's cache.|#]
> [#|2011-07-18T16:29:41.959-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerCache;MethodName=removeTimer;|Removing
> timer 1@@1311031751968@@h002-batch@@h002-batch|#]
>
>
> On Mon, Jul 18, 2011 at 10:43 AM, > wrote:
>
> Can you try with javax.enterprise.system.container.ejb.level=FINE?
>
>
> --
>
> [Message sent by forum member 'cf126330']
>
> View Post: http://forums.java.net/node/823173
>
>
>

whshub
Offline
Joined: 2010-02-27

Thanks for your quick response. Adding the system property below does allow
the timer to operate correctly as far as I can see.

What are the risks of using this flag/property?

Do you have a bug number for this bug so I can follow it? Do you know
specifically when this bug occurs? Is it all transient timers in a
clustered environment, only within an ear, only on singleton?

Thanks again for your help.

Jacques

On Mon, Jul 18, 2011 at 4:47 PM, Marina Vatkina
wrote:

> It's a bug (strangely it works in our tests). Try setting System property
> "com.sun.ejb.timer.**ReadDBBeforeTimeout=false".
>
> thanks,
> -marina
>
> Jacques wrote:
>
>> I re-ran with the updated logging. I see a log event that says the timer
>> was cancelled by another instance. How would that happen?
>>
>> I tried to attach appropriate log lines below. First part is during
>> deployment. Second part is timer expiration.
>>
>> thanks for any help,
>> Jacques
>>
>> ====DEPLOY========
>> [#|2011-07-18T16:29:09.143-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=postInvoke;|Leaving
>> BaseContainer::postInvoke : EjbInvocation componentId=ejb-timer-service-
>> **app_/ejb-timer-service-app,**isLocal=true,isRemote=false,**
>> isBusinessInterface=true,**isWebService=false,**
>> isMessageDriven=false,isHome=**false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract java.util.Set
>> com.sun.ejb.containers.**TimerLocal.**findActiveTimersOwnedByThisSer**
>> verByContainer(long),ejb=com.**sun.ejb.containers.TimerBean@**
>> 851bfe0,exception=null,**exceptionFromBeanMethod=null,**
>> invId=0,wasCancelCalled=false,**yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:09.144-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=_**restoreTimers;|DONE
>> EJBTimerService.restoreTimers(**)|#]
>> [#|2011-07-18T16:29:11.968-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**createTimer;|@@@ Created timer [1@
>> @1311031751968@@h002-batch@**@h002-batch] with the first expiration set
>> to: Mon Jul 18 16:29:41 PDT 2011|#]
>> [#|2011-07-18T16:29:11.970-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> RuntimeTimerState;MethodName=<**init>;|RuntimeTimerState 1@
>> @1311031751968@@h002-batch@@**h002-batch created|#]
>> [#|2011-07-18T16:29:11.971-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService$TimerCache;**MethodName=addTimer;|Adding timer '1@
>> @1311031751968@@h002-batch@**@h002-batch' 'TimedObject =
>> DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED' 'PERIODIC'
>> 'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000'
>> |#]
>> [#|2011-07-18T16:29:11.999-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService$TimerSynch;**MethodName=afterCompletion;|**TimerSynch::afterCompletion.
>> timer state = TIMER_ACTIVE , timer id = 1@@1311031751968@@h002-batch@@**h002-batch
>> , JTA TX status = TX_STATUS_COMMITTED , timeout = Mon Jul 18 16:29:41 PDT
>> 2011|#]
>> [#|2011-07-18T16:29:12.000-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**scheduleTask;|Scheduling '1@@1311031751968@
>> @h002-batch@**@h002-batch' 'TimedObject = DatabaseIntermdiaryImpl'
>> 'Application = batch' 'CREATED' 'PERIODIC' 'Container ID =
>> 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000' for timeout at
>> Mon Jul 18 16:29:41 PDT 2011|#]
>> [#|2011-07-18T16:29:12.011-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=preInvoke;|Entering
>> BaseContainer::preInvoke : EjbInvocation componentId=ejb-timer-service-*
>> *app_/ejb-timer-service-app,**isLocal=true,isRemote=false,**
>> isBusinessInterface=true,**isWebService=false,**
>> isMessageDriven=false,isHome=**false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract java.util.Set
>> com.sun.ejb.containers.**TimerLocal.**findActiveTimersOwnedByThisSer**
>> verByContainer(long),ejb=null,**exception=null,**
>> exceptionFromBeanMethod=null,**invId=0,wasCancelCalled=false,**
>> yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:12.011-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=124;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**authorize;|JACC: Access Control Decision
>> Result: true EJBMethodPermission (Name) = TimerBean (Action) =
>> findActiveTimersOwnedByThisSer**verByContainer,Local,long (Caller) =
>> null|#]
>> [#|2011-07-18T16:29:12.013-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=postInvoke;|Leaving
>> BaseContainer::postInvoke : EjbInvocation componentId=ejb-timer-service-
>> **app_/ejb-timer-service-app,**isLocal=true,isRemote=false,**
>> isBusinessInterface=true,**isWebService=false,**
>> isMessageDriven=false,isHome=**false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract java.util.Set
>> com.sun.ejb.containers.**TimerLocal.**findActiveTimersOwnedByThisSer**
>> verByContainer(long),ejb=com.**sun.ejb.containers.TimerBean@**
>> 851bfe0,exception=null,**exceptionFromBeanMethod=null,**
>> invId=0,wasCancelCalled=false,**yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:12.013-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=_**restoreTimers;|DONE
>> EJBTimerService.restoreTimers(**)|#]
>>
>>
>>
>>
>> ======EXPIRATION======
>> [#|2011-07-18T16:29:41.945-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=144;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**taskExpired;|Adding work pool task for timer
>> 1@@1311031751968@@h002-batch@@**h002-batch|#]
>> [#|2011-07-18T16:29:41.946-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**deliverTimeout;|**EJBTimerService.**deliverTimeout():
>> work thread is processing work for timerId = 1@@1311031751968@
>> @h002-batch@@**h002-batch|#]
>> [#|2011-07-18T16:29:41.947-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**deliverTimeout;|Calling ejbTimeout for timer
>> '1@@1311031751968@@h002-batch@**@h002-batch' 'TimedObject =
>> DatabaseIntermdiaryImpl' 'Application = batch' 'BEING_DELIVERED' 'PERIODIC'
>> 'Container ID = 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000'
>> |#]
>> [#|2011-07-18T16:29:41.947-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**deliverTimeout;|For Timer :1@@1311031751968@
>> @h002-batch@**@h002-batch: check the database to ensure that the timer is
>> still valid, before delivering the ejbTimeout call|#]
>> [#|2011-07-18T16:29:41.948-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=preInvoke;|Entering
>> BaseContainer::preInvoke : EjbInvocation componentId=ejb-timer-service-*
>> *app_/ejb-timer-service-app,**isLocal=true,isRemote=false,**
>> isBusinessInterface=true,**isWebService=false,**
>> isMessageDriven=false,isHome=**false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> com.sun.ejb.containers.**TimerState com.sun.ejb.containers.**
>> TimerLocal.findTimer(com.sun.**ejb.containers.**
>> TimerPrimaryKey),ejb=null,**exception=null,**
>> exceptionFromBeanMethod=null,**invId=0,wasCancelCalled=false,**
>> yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:41.948-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=199;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**authorize;|JACC: permission initialized
>> in InvocationInfo: EJBMethodPermission (Name) = TimerBean (Action) =
>> findTimer,Local,com.sun.ejb.**containers.TimerPrimaryKey|#]
>> [#|2011-07-18T16:29:41.949-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=199;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**authorize;|JACC: Access Control Decision
>> Result: true EJBMethodPermission (Name) = TimerBean (Action) =
>> findTimer,Local,com.sun.ejb.**containers.TimerPrimaryKey (Caller) =
>> null|#]
>> [#|2011-07-18T16:29:41.950-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=199;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**resetPolicyContext;|JACC: Changing Policy
>> Context ID: oldV = null newV = ejb-timer-service-app/ejb-**
>> timer-service-app_internal|#]
>> [#|2011-07-18T16:29:41.958-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=postInvoke;|Leaving
>> BaseContainer::postInvoke : EjbInvocation componentId=ejb-timer-service-
>> **app_/ejb-timer-service-app,**isLocal=true,isRemote=false,**
>> isBusinessInterface=true,**isWebService=false,**
>> isMessageDriven=false,isHome=**false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> com.sun.ejb.containers.**TimerState com.sun.ejb.containers.**
>> TimerLocal.findTimer(com.sun.**ejb.containers.**
>> TimerPrimaryKey),ejb=com.sun.**ejb.containers.TimerBean@**
>> 851bfe0,exception=null,**exceptionFromBeanMethod=null,**
>> invId=0,wasCancelCalled=false,**yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:41.959-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**getValidTimerFromDB;|Timer :1@
>> @1311031751968@@h002-batch@**@h002-batch: has been cancelled by another
>> server instance. Expunging the timer from h002-batch's cache.|#]
>> [#|2011-07-18T16:29:41.959-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService$TimerCache;**MethodName=removeTimer;|**Removing timer 1@
>> @1311031751968@@h002-batch@@**h002-batch|#]
>>
>>
>> On Mon, Jul 18, 2011 at 10:43 AM, > >> wrote:
>>
>> Can you try with javax.enterprise.system.**container.ejb.level=FINE?
>>
>>
>> --
>>
>> [Message sent by forum member 'cf126330']
>>
>> View Post: http://forums.java.net/node/**823173
>>
>>
>>
>>

mvatkina
Offline
Joined: 2005-04-04

Jacques,

Jacques wrote:
> Thanks for your quick response. Adding the system property below does
> allow the timer to operate correctly as far as I can see.
>
> What are the risks of using this flag/property?

Shouldn't be because the data shouldn't be cashed anyway.
>
> Do you have a bug number for this bug so I can follow it?

You'd need to file it :)
> Do you know specifically when this bug occurs?

For non-persistent timers on a clustered instance.
> Is it all transient timers in a clustered environment, only within an
> ear, only on singleton?

Any. The previous if() statement wasn't adjusted for the non-persistent
timers case. So there is a check that the timer still exists in the db,
and because it is not, the code says - oh, it's canceled on another
instance. But the transient timers are not there in DB in the 1st place :(.

The 'false' setting should be safe (otherwise raise a support issue and
they should be able to provide a patch) because each timer runs in only
1 instance.

>
> Thanks again for your help.

Sorry for the bug :(.

-marina
>
> Jacques
>
> On Mon, Jul 18, 2011 at 4:47 PM, Marina Vatkina
> > wrote:
>
> It's a bug (strangely it works in our tests). Try setting System
> property "com.sun.ejb.timer.ReadDBBeforeTimeout=false".
>
> thanks,
> -marina
>
> Jacques wrote:
>
> I re-ran with the updated logging. I see a log event that
> says the timer was cancelled by another instance. How would
> that happen?
>
> I tried to attach appropriate log lines below. First part is
> during deployment. Second part is timer expiration.
>
> thanks for any help,
> Jacques
>
> ====DEPLOY========
> [#|2011-07-18T16:29:09.143-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
> BaseContainer::postInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> java.util.Set
> com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=com.sun.ejb.containers.TimerBean@851bfe0,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:09.144-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=_restoreTimers;|DONE
> EJBTimerService.restoreTimers()|#]
> [#|2011-07-18T16:29:11.968-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=createTimer;|@@@
> Created timer [1@@1311031751968@@h002-batch@@h002-batch] with
> the first expiration set to: Mon Jul 18 16:29:41 PDT 2011|#]
> [#|2011-07-18T16:29:11.970-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.RuntimeTimerState;MethodName=;|RuntimeTimerState
> 1@@1311031751968@@h002-batch@@h002-batch created|#]
> [#|2011-07-18T16:29:11.971-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerCache;MethodName=addTimer;|Adding
> timer '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject
> = DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED'
> 'PERIODIC' 'Container ID = 85917732333944859' 'Mon Jul 18
> 16:29:41 PDT 2011' '60000' |#]
> [#|2011-07-18T16:29:11.999-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerSynch;MethodName=afterCompletion;|TimerSynch::afterCompletion.
> timer state = TIMER_ACTIVE , timer id =
> 1@@1311031751968@@h002-batch@@h002-batch , JTA TX status =
> TX_STATUS_COMMITTED , timeout = Mon Jul 18 16:29:41 PDT 2011|#]
> [#|2011-07-18T16:29:12.000-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=scheduleTask;|Scheduling
> '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject =
> DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED'
> 'PERIODIC' 'Container ID = 85917732333944859' 'Mon Jul 18
> 16:29:41 PDT 2011' '60000' for timeout at Mon Jul 18 16:29:41
> PDT 2011|#]
> [#|2011-07-18T16:29:12.011-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering
> BaseContainer::preInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> java.util.Set
> com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:12.011-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=124;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
> Access Control Decision Result: true EJBMethodPermission
> (Name) = TimerBean (Action) =
> findActiveTimersOwnedByThisServerByContainer,Local,long
> (Caller) = null|#]
> [#|2011-07-18T16:29:12.013-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
> BaseContainer::postInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> java.util.Set
> com.sun.ejb.containers.TimerLocal.findActiveTimersOwnedByThisServerByContainer(long),ejb=com.sun.ejb.containers.TimerBean@851bfe0,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:12.013-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=124;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=_restoreTimers;|DONE
> EJBTimerService.restoreTimers()|#]
>
>
>
>
> ======EXPIRATION======
> [#|2011-07-18T16:29:41.945-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=144;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=taskExpired;|Adding
> work pool task for timer
> 1@@1311031751968@@h002-batch@@h002-batch|#]
> [#|2011-07-18T16:29:41.946-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|EJBTimerService.deliverTimeout():
> work thread is processing work for timerId =
> 1@@1311031751968@@h002-batch@@h002-batch|#]
> [#|2011-07-18T16:29:41.947-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|Calling
> ejbTimeout for timer
> '1@@1311031751968@@h002-batch@@h002-batch' 'TimedObject =
> DatabaseIntermdiaryImpl' 'Application = batch'
> 'BEING_DELIVERED' 'PERIODIC' 'Container ID =
> 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000' |#]
> [#|2011-07-18T16:29:41.947-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=deliverTimeout;|For
> Timer :1@@1311031751968@@h002-batch@@h002-batch: check the
> database to ensure that the timer is still valid, before
> delivering the ejbTimeout call|#]
> [#|2011-07-18T16:29:41.948-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=preInvoke;|Entering
> BaseContainer::preInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> com.sun.ejb.containers.TimerState
> com.sun.ejb.containers.TimerLocal.findTimer(com.sun.ejb.containers.TimerPrimaryKey),ejb=null,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:41.948-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
> permission initialized in InvocationInfo: EJBMethodPermission
> (Name) = TimerBean (Action) =
> findTimer,Local,com.sun.ejb.containers.TimerPrimaryKey|#]
> [#|2011-07-18T16:29:41.949-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=authorize;|JACC:
> Access Control Decision Result: true EJBMethodPermission
> (Name) = TimerBean (Action) =
> findTimer,Local,com.sun.ejb.containers.TimerPrimaryKey
> (Caller) = null|#]
> [#|2011-07-18T16:29:41.950-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.org.glassfish.ejb.security.application|_ThreadID=199;_ThreadName=Thread-1;ClassName=org.glassfish.ejb.security.application.EJBSecurityManager;MethodName=resetPolicyContext;|JACC:
> Changing Policy Context ID: oldV = null newV =
> ejb-timer-service-app/ejb-timer-service-app_internal|#]
> [#|2011-07-18T16:29:41.958-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.BaseContainer;MethodName=postInvoke;|Leaving
> BaseContainer::postInvoke : EjbInvocation
> componentId=ejb-timer-service-app_/ejb-timer-service-app,isLocal=true,isRemote=false,isBusinessInterface=true,isWebService=false,isMessageDriven=false,isHome=false,clientInterface=interface
> com.sun.ejb.containers.TimerLocal,method=public abstract
> com.sun.ejb.containers.TimerState
> com.sun.ejb.containers.TimerLocal.findTimer(com.sun.ejb.containers.TimerPrimaryKey),ejb=com.sun.ejb.containers.TimerBean@851bfe0,exception=null,exceptionFromBeanMethod=null,invId=0,wasCancelCalled=false,yetToSubmitStatus=true|#]
> [#|2011-07-18T16:29:41.959-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService;MethodName=getValidTimerFromDB;|Timer
> :1@@1311031751968@@h002-batch@@h002-batch: has been cancelled
> by another server instance. Expunging the timer from
> h002-batch's cache.|#]
> [#|2011-07-18T16:29:41.959-0700|FINE|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=199;_ThreadName=Thread-1;ClassName=com.sun.ejb.containers.EJBTimerService$TimerCache;MethodName=removeTimer;|Removing
> timer 1@@1311031751968@@h002-batch@@h002-batch|#]
>
>
> On Mon, Jul 18, 2011 at 10:43 AM, >> wrote:
>
> Can you try with
> javax.enterprise.system.container.ejb.level=FINE?
>
>
> --
>
> [Message sent by forum member 'cf126330']
>
> View Post: http://forums.java.net/node/823173
>
>
>
>

whshub
Offline
Joined: 2010-02-27

I filed it under GLASSFISH-17060.

Thanks again for your help. It's always nice to find out that we're not
going crazy...

Jacques

On Mon, Jul 18, 2011 at 5:31 PM, Marina Vatkina
wrote:

> Jacques,
>
>
> Jacques wrote:
>
>> Thanks for your quick response. Adding the system property below does
>> allow the timer to operate correctly as far as I can see.
>>
>> What are the risks of using this flag/property?
>>
>
> Shouldn't be because the data shouldn't be cashed anyway.
>
>
>> Do you have a bug number for this bug so I can follow it?
>>
>
> You'd need to file it :)
>
> Do you know specifically when this bug occurs?
>>
>
> For non-persistent timers on a clustered instance.
>
> Is it all transient timers in a clustered environment, only within an ear,
>> only on singleton?
>>
>
> Any. The previous if() statement wasn't adjusted for the non-persistent
> timers case. So there is a check that the timer still exists in the db, and
> because it is not, the code says - oh, it's canceled on another instance.
> But the transient timers are not there in DB in the 1st place :(.
>
> The 'false' setting should be safe (otherwise raise a support issue and
> they should be able to provide a patch) because each timer runs in only 1
> instance.
>
>
>
>> Thanks again for your help.
>>
>
> Sorry for the bug :(.
>
> -marina
>
>>
>> Jacques
>>
>>
>> On Mon, Jul 18, 2011 at 4:47 PM, Marina Vatkina <
>> marina.vatkina... >>
>> wrote:
>>
>> It's a bug (strangely it works in our tests). Try setting System
>> property "com.sun.ejb.timer.**ReadDBBeforeTimeout=false".
>>
>> thanks,
>> -marina
>>
>> Jacques wrote:
>>
>> I re-ran with the updated logging. I see a log event that
>> says the timer was cancelled by another instance. How would
>> that happen?
>>
>> I tried to attach appropriate log lines below. First part is
>> during deployment. Second part is timer expiration.
>>
>> thanks for any help,
>> Jacques
>>
>> ====DEPLOY========
>> [#|2011-07-18T16:29:09.143-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=postInvoke;|Leaving
>> BaseContainer::postInvoke : EjbInvocation
>> componentId=ejb-timer-service-**app_/ejb-timer-service-app,**
>> isLocal=true,isRemote=false,**isBusinessInterface=true,**
>> isWebService=false,**isMessageDriven=false,isHome=**
>> false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> java.util.Set
>> com.sun.ejb.containers.**TimerLocal.**
>> findActiveTimersOwnedByThisSer**verByContainer(long),ejb=com.**
>> sun.ejb.containers.TimerBean@**851bfe0,exception=null,**
>> exceptionFromBeanMethod=null,**invId=0,wasCancelCalled=false,**
>> yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:09.144-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=_**restoreTimers;|DONE
>> EJBTimerService.restoreTimers(**)|#]
>> [#|2011-07-18T16:29:11.968-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**createTimer;|@@@
>> Created timer [1@@1311031751968@@h002-batch@**@h002-batch] with
>> the first expiration set to: Mon Jul 18 16:29:41 PDT 2011|#]
>> [#|2011-07-18T16:29:11.970-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> RuntimeTimerState;MethodName=<**init>;|RuntimeTimerState
>> 1@@1311031751968@@h002-batch@@**h002-batch created|#]
>> [#|2011-07-18T16:29:11.971-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService$TimerCache;**MethodName=addTimer;|Adding
>> timer '1@@1311031751968@@h002-batch@**@h002-batch' 'TimedObject
>> = DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED'
>> 'PERIODIC' 'Container ID = 85917732333944859' 'Mon Jul 18
>> 16:29:41 PDT 2011' '60000' |#]
>> [#|2011-07-18T16:29:11.999-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService$TimerSynch;**MethodName=afterCompletion;|**
>> TimerSynch::afterCompletion.
>> timer state = TIMER_ACTIVE , timer id =
>> 1@@1311031751968@@h002-batch@@**h002-batch , JTA TX status =
>> TX_STATUS_COMMITTED , timeout = Mon Jul 18 16:29:41 PDT 2011|#]
>> [#|2011-07-18T16:29:12.000-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**scheduleTask;|Scheduling
>> '1@@1311031751968@@h002-batch@**@h002-batch' 'TimedObject =
>> DatabaseIntermdiaryImpl' 'Application = batch' 'CREATED'
>> 'PERIODIC' 'Container ID = 85917732333944859' 'Mon Jul 18
>> 16:29:41 PDT 2011' '60000' for timeout at Mon Jul 18 16:29:41
>> PDT 2011|#]
>> [#|2011-07-18T16:29:12.011-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=preInvoke;|Entering
>> BaseContainer::preInvoke : EjbInvocation
>> componentId=ejb-timer-service-**app_/ejb-timer-service-app,**
>> isLocal=true,isRemote=false,**isBusinessInterface=true,**
>> isWebService=false,**isMessageDriven=false,isHome=**
>> false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> java.util.Set
>> com.sun.ejb.containers.**TimerLocal.**
>> findActiveTimersOwnedByThisSer**verByContainer(long),ejb=null,**
>> exception=null,**exceptionFromBeanMethod=null,**
>> invId=0,wasCancelCalled=false,**yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:12.011-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=124;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**authorize;|JACC:
>> Access Control Decision Result: true EJBMethodPermission
>> (Name) = TimerBean (Action) =
>> findActiveTimersOwnedByThisSer**verByContainer,Local,long
>> (Caller) = null|#]
>> [#|2011-07-18T16:29:12.013-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=postInvoke;|Leaving
>> BaseContainer::postInvoke : EjbInvocation
>> componentId=ejb-timer-service-**app_/ejb-timer-service-app,**
>> isLocal=true,isRemote=false,**isBusinessInterface=true,**
>> isWebService=false,**isMessageDriven=false,isHome=**
>> false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> java.util.Set
>> com.sun.ejb.containers.**TimerLocal.**
>> findActiveTimersOwnedByThisSer**verByContainer(long),ejb=com.**
>> sun.ejb.containers.TimerBean@**851bfe0,exception=null,**
>> exceptionFromBeanMethod=null,**invId=0,wasCancelCalled=false,**
>> yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:12.013-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=124;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=_**restoreTimers;|DONE
>> EJBTimerService.restoreTimers(**)|#]
>>
>>
>>
>>
>> ======EXPIRATION======
>> [#|2011-07-18T16:29:41.945-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=144;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**taskExpired;|Adding
>> work pool task for timer
>> 1@@1311031751968@@h002-batch@@**h002-batch|#]
>> [#|2011-07-18T16:29:41.946-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**deliverTimeout;|**EJBTimerService.**
>> deliverTimeout():
>> work thread is processing work for timerId =
>> 1@@1311031751968@@h002-batch@@**h002-batch|#]
>> [#|2011-07-18T16:29:41.947-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**deliverTimeout;|Calling
>> ejbTimeout for timer
>> '1@@1311031751968@@h002-batch@**@h002-batch' 'TimedObject =
>> DatabaseIntermdiaryImpl' 'Application = batch'
>> 'BEING_DELIVERED' 'PERIODIC' 'Container ID =
>> 85917732333944859' 'Mon Jul 18 16:29:41 PDT 2011' '60000' |#]
>> [#|2011-07-18T16:29:41.947-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**deliverTimeout;|For
>> Timer :1@@1311031751968@@h002-batch@**@h002-batch: check the
>> database to ensure that the timer is still valid, before
>> delivering the ejbTimeout call|#]
>> [#|2011-07-18T16:29:41.948-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=preInvoke;|Entering
>> BaseContainer::preInvoke : EjbInvocation
>> componentId=ejb-timer-service-**app_/ejb-timer-service-app,**
>> isLocal=true,isRemote=false,**isBusinessInterface=true,**
>> isWebService=false,**isMessageDriven=false,isHome=**
>> false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> com.sun.ejb.containers.**TimerState
>> com.sun.ejb.containers.**TimerLocal.findTimer(com.sun.**
>> ejb.containers.**TimerPrimaryKey),ejb=null,**exception=null,**
>> exceptionFromBeanMethod=null,**invId=0,wasCancelCalled=false,**
>> yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:41.948-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=199;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**authorize;|JACC:
>> permission initialized in InvocationInfo: EJBMethodPermission
>> (Name) = TimerBean (Action) =
>> findTimer,Local,com.sun.ejb.**containers.TimerPrimaryKey|#]
>> [#|2011-07-18T16:29:41.949-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=199;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**authorize;|JACC:
>> Access Control Decision Result: true EJBMethodPermission
>> (Name) = TimerBean (Action) =
>> findTimer,Local,com.sun.ejb.**containers.TimerPrimaryKey
>> (Caller) = null|#]
>> [#|2011-07-18T16:29:41.950-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.org.glassfish.ejb.**
>> security.application|_**ThreadID=199;_ThreadName=**
>> Thread-1;ClassName=org.**glassfish.ejb.security.**application.**
>> EJBSecurityManager;MethodName=**resetPolicyContext;|JACC:
>> Changing Policy Context ID: oldV = null newV =
>> ejb-timer-service-app/ejb-**timer-service-app_internal|#]
>> [#|2011-07-18T16:29:41.958-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**
>> ejb.containers.BaseContainer;**MethodName=postInvoke;|Leaving
>> BaseContainer::postInvoke : EjbInvocation
>> componentId=ejb-timer-service-**app_/ejb-timer-service-app,**
>> isLocal=true,isRemote=false,**isBusinessInterface=true,**
>> isWebService=false,**isMessageDriven=false,isHome=**
>> false,clientInterface=**interface
>> com.sun.ejb.containers.**TimerLocal,method=public abstract
>> com.sun.ejb.containers.**TimerState
>> com.sun.ejb.containers.**TimerLocal.findTimer(com.sun.**
>> ejb.containers.**TimerPrimaryKey),ejb=com.sun.**ejb.containers.TimerBean@
>> **851bfe0,exception=null,**exceptionFromBeanMethod=null,**
>> invId=0,wasCancelCalled=false,**yetToSubmitStatus=true|#]
>> [#|2011-07-18T16:29:41.959-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService;MethodName=**getValidTimerFromDB;|Timer
>> :1@@1311031751968@@h002-batch@**@h002-batch: has been cancelled
>> by another server instance. Expunging the timer from
>> h002-batch's cache.|#]
>> [#|2011-07-18T16:29:41.959-**0700|FINE|glassfish3.1|javax.**
>> enterprise.system.container.**ejb.com.sun.ejb.containers|_**
>> ThreadID=199;_ThreadName=**Thread-1;ClassName=com.sun.**ejb.containers.**
>> EJBTimerService$TimerCache;**MethodName=removeTimer;|**Removing
>> timer 1@@1311031751968@@h002-batch@@**h002-batch|#]
>>
>>
>> On Mon, Jul 18, 2011 at 10:43 AM, > >
>> >> wrote:
>>
>> Can you try with
>> javax.enterprise.system.**container.ejb.level=FINE?
>>
>>
>> --
>>
>> [Message sent by forum member 'cf126330']
>>
>> View Post: http://forums.java.net/node/**823173
>>
>>
>>
>>
>>