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_at_oracle.com <mailto:marina.vatkina_at_oracle.com>> 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_at_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.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_at_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_at_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, <forums_at_java.net
> <mailto:forums_at_java.net> <mailto:forums_at_java.net
> <mailto:forums_at_java.net>>> 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
>
>
>
>