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> 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<http://forums.java.net/node/823173>
>
>
>