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
<marina.vatkina_at_oracle.com>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_at_oracle.com <mailto:marina.vatkina_at_oracle.**com<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> <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<http://forums.java.net/node/823173>
>>
>>
>>
>>
>>