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