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