Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-19361

EJB timer executed before the @PostConstruct of a @Singleton @Startup bean has finished with HA profile

XMLWordPrintable

      In an @Singleton, @Startup bean, an EJB timer is being cancelled and then created in the @PostConstruct method like this:

          @PostConstruct
    public void initialize() {

        logger.info("INIT: going to cancel");
        cancelTimer(TIMER_INFO_TEMPLATE);

        long intervall = Long.getLong("timer.intervall", 30000l);
        logger.infof("INIT: Timertest: %d ( %d min)", intervall, (intervall / 1000 / 60));

        TimerConfig test = new TimerConfig(String.format(TIMER_INFO_TEMPLATE, LocalDateTime.now()), true);
        timerService.createIntervalTimer(2000, intervall, test);
    }

    void cancelTimer(String timerId) {
        timerService.getTimers().stream().forEach(t -> {

            logger.infof("Timer: id: %s, info: %s, class: %s", t, t.getInfo(), t.getClass());
            try {
                t.cancel();
            }
            catch (Exception e) {
                logger.infof(e, "cancelTimer abort: %s e: %s", t.getInfo(), e.getMessage());
            }
        });
    }

      If this bean had been deployed on a WildFly server using an unmodified HA profile, this persistent timer is not removed when undeploying the application, which is expected and correct.

      Once this application is deployed again, it seems the timer is executed during the server start, before the @PostConstruct method has finished, in case the timer would have expired while the application was undeployed. This lead to an Infinispan timeout like this:

      2024-05-28 10:39:55,703 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (non-blocking-thread--p7-t11) ISPN000136: Error executing command GetKeyValueCommand on Cache 'playground.war.TestTimer.PERSISTENT', writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key InfinispanTimerMetaDataKey(19fa67fd-151b-49a6-a9fe-462f04523aa7) and requestor GlobalTransaction{id=4, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=3, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:299)
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:229)
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.checkState(InfinispanLock.java:440)
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lambda$toInvocationStage$3(InfinispanLock.java:416)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.wildfly.clustering.context@32.0.0.Final//org.wildfly.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:32)
	at org.wildfly.clustering.context@32.0.0.Final//org.wildfly.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:61)
	at java.base/java.lang.Thread.run(Thread.java:829)

2024-05-28 10:39:55,711 INFO  [org.jboss.playground.ejb.TestTimer] (TimerScheduler - 2) INIT: going to cancel
2024-05-28 10:39:55,710 ERROR [org.jboss.msc.service.fail] (ServerService Thread Pool -- 34) MSC000001: Failed to start service jboss.deployment.unit."playground.war".component.TestTimer.START: org.jboss.msc.service.StartException in service jboss.deployment.unit."playground.war".component.TestTimer.START: java.lang.IllegalStateException: WFLYEE0042: Failed to construct component instance
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ComponentStartService$1.run(ComponentStartService.java:40)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at java.base/java.lang.Thread.run(Thread.java:829)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.JBossThread.run(JBossThread.java:513)
Caused by: java.lang.IllegalStateException: WFLYEE0042: Failed to construct component instance
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.constructComponentInstance(BasicComponent.java:153)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.constructComponentInstance(BasicComponent.java:124)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.createInstance(BasicComponent.java:71)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.SingletonComponent.getComponentInstance(SingletonComponent.java:110)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.SingletonComponent.start(SingletonComponent.java:124)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ComponentStartService$1.run(ComponentStartService.java:37)
	... 8 more
Caused by: jakarta.ejb.EJBException: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key InfinispanTimerMetaDataKey(19fa67fd-151b-49a6-a9fe-462f04523aa7) and requestor GlobalTransaction{id=4, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=3, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:251)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:399)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.LifecycleCMTTxInterceptor.processInvocation(LifecycleCMTTxInterceptor.java:51)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.injection.WeldInjectionContextInterceptor.processInvocation(WeldInjectionContextInterceptor.java:26)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:24)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:28)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.StartupCountDownInterceptor.processInvocation(StartupCountDownInterceptor.java:30)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.constructComponentInstance(BasicComponent.java:151)
	... 13 more
Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key InfinispanTimerMetaDataKey(19fa67fd-151b-49a6-a9fe-462f04523aa7) and requestor GlobalTransaction{id=4, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=3, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}
	at org.infinispan.core@14.0.27.Final//org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:258)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:323)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:111)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:543)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:537)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:762)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:431)
	at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:431)
	at org.wildfly.clustering.ejb.infinispan@32.0.0.Final//org.wildfly.clustering.ejb.infinispan.timer.InfinispanTimerMetaDataFactory.findValue(InfinispanTimerMetaDataFactory.java:62)
	at org.wildfly.clustering.ejb.infinispan@32.0.0.Final//org.wildfly.clustering.ejb.infinispan.timer.InfinispanTimerMetaDataFactory.findValue(InfinispanTimerMetaDataFactory.java:33)
	at org.wildfly.clustering.ejb.infinispan@32.0.0.Final//org.wildfly.clustering.ejb.infinispan.timer.InfinispanTimerManager.getTimer(InfinispanTimerManager.java:167)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.distributable.OOBTimer.invoke(OOBTimer.java:158)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.distributable.OOBTimer.getInfo(OOBTimer.java:99)
	at deployment.playground.war//org.jboss.playground.ejb.TestTimer.lambda$cancelTimer$0(TestTimer.java:62)
	at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
	at deployment.playground.war//org.jboss.playground.ejb.TestTimer.cancelTimer(TestTimer.java:60)
	at deployment.playground.war//org.jboss.playground.ejb.TestTimer.initialize(TestTimer.java:48)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:79)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:62)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doLifecycleInterception(Jsr299BindingsInterceptor.java:109)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:95)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.weld.core@5.1.2.Final//org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:87)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:72)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.injection.WeldInjectionInterceptor.processInvocation(WeldInjectionInterceptor.java:36)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ManagedReferenceFieldInjectionInterceptorFactory$ManagedReferenceFieldInjectionInterceptor.processInvocation(ManagedReferenceFieldInjectionInterceptorFactory.java:95)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.AroundConstructInterceptorFactory$1.processInvocation(AroundConstructInterceptorFactory.java:33)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.injection.WeldInterceptorInjectionInterceptor.processInvocation(WeldInterceptorInjectionInterceptor.java:39)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsCreateInterceptor.processInvocation(Jsr299BindingsCreateInterceptor.java:94)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:33)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:237)
	... 28 more
Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key InfinispanTimerMetaDataKey(19fa67fd-151b-49a6-a9fe-462f04523aa7) and requestor GlobalTransaction{id=4, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}. Lock is held by GlobalTransaction{id=3, addr=primary:ha-node-1, remote=false, xid=null, internalId=-1}
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:299)
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:229)
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.checkState(InfinispanLock.java:440)
	at org.infinispan.core@14.0.27.Final//org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.lambda$toInvocationStage$3(InfinispanLock.java:416)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642)
	at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.wildfly.clustering.context@32.0.0.Final//org.wildfly.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:32)
	at org.wildfly.clustering.context@32.0.0.Final//org.wildfly.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:61)
	at java.base/java.lang.Thread.run(Thread.java:829)
	Suppressed: org.infinispan.commons.util.logging.TraceException
		at org.infinispan.core@14.0.27.Final//org.infinispan.interceptors.impl.SimpleAsyncInvocationStage.get(SimpleAsyncInvocationStage.java:39)
		at org.infinispan.core@14.0.27.Final//org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:249)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:323)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:111)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:543)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:537)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.EncoderCache.get(EncoderCache.java:762)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:431)
		at org.infinispan.core@14.0.27.Final//org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:431)
		at org.wildfly.clustering.ejb.infinispan@32.0.0.Final//org.wildfly.clustering.ejb.infinispan.timer.InfinispanTimerMetaDataFactory.findValue(InfinispanTimerMetaDataFactory.java:62)
		at org.wildfly.clustering.ejb.infinispan@32.0.0.Final//org.wildfly.clustering.ejb.infinispan.timer.InfinispanTimerMetaDataFactory.findValue(InfinispanTimerMetaDataFactory.java:33)
		at org.wildfly.clustering.ejb.infinispan@32.0.0.Final//org.wildfly.clustering.ejb.infinispan.timer.InfinispanTimerManager.getTimer(InfinispanTimerManager.java:167)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.distributable.OOBTimer.invoke(OOBTimer.java:158)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.distributable.OOBTimer.getInfo(OOBTimer.java:99)
		at deployment.playground.war//org.jboss.playground.ejb.TestTimer.lambda$cancelTimer$0(TestTimer.java:62)
		at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
		at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
		at deployment.playground.war//org.jboss.playground.ejb.TestTimer.cancelTimer(TestTimer.java:60)
		at deployment.playground.war//org.jboss.playground.ejb.TestTimer.initialize(TestTimer.java:48)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
		at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
		at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
		at java.base/java.lang.reflect.Method.invoke(Method.java:566)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:79)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
		at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:62)
		at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doLifecycleInterception(Jsr299BindingsInterceptor.java:109)
		at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:95)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
		at org.jboss.weld.core@5.1.2.Final//org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:87)
		at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:72)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.injection.WeldInjectionInterceptor.processInvocation(WeldInjectionInterceptor.java:36)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ManagedReferenceFieldInjectionInterceptorFactory$ManagedReferenceFieldInjectionInterceptor.processInvocation(ManagedReferenceFieldInjectionInterceptorFactory.java:95)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.AroundConstructInterceptorFactory$1.processInvocation(AroundConstructInterceptorFactory.java:33)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.injection.WeldInterceptorInjectionInterceptor.processInvocation(WeldInterceptorInjectionInterceptor.java:39)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsCreateInterceptor.processInvocation(Jsr299BindingsCreateInterceptor.java:94)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:33)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:237)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew(CMTTxInterceptor.java:399)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.LifecycleCMTTxInterceptor.processInvocation(LifecycleCMTTxInterceptor.java:51)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.weld@32.0.0.Final//org.jboss.as.weld.injection.WeldInjectionContextInterceptor.processInvocation(WeldInjectionContextInterceptor.java:26)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:24)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:28)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.StartupCountDownInterceptor.processInvocation(StartupCountDownInterceptor.java:30)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
		at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.constructComponentInstance(BasicComponent.java:151)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.constructComponentInstance(BasicComponent.java:124)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.BasicComponent.createInstance(BasicComponent.java:71)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.SingletonComponent.getComponentInstance(SingletonComponent.java:110)
		at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.SingletonComponent.start(SingletonComponent.java:124)
		at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ComponentStartService$1.run(ComponentStartService.java:37)
		at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
		at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
		at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
		at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
		at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
		at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
		at java.base/java.lang.Thread.run(Thread.java:829)
		at org.jboss.threads@2.4.0.Final//org.jboss.threads.JBossThread.run(JBossThread.java:513)

      Note: This happens with the new Infinispan based clustered EJB timer

      When running with a clustered EJB timer using database-data-store, this does no happen and the timer is correctly cancelled and then created afterwards again, see:

      2024-05-28 10:50:12,285 INFO  [org.jboss.playground.ejb.TestTimer] (ServerService Thread Pool -- 28) INIT: going to cancel
2024-05-28 10:50:12,285 INFO  [org.jboss.playground.ejb.TestTimer] (ServerService Thread Pool -- 28) Timer: id: [id=d5c139d8-8bd9-4fd8-bd17-fb7686af2f16 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=2024-05-28 10:49:50.0 initialExpiration=2024-05-28 10:49:20.0 intervalDuration(in milli sec)=10000 nextExpiration=2024-05-28 10:50:00.0 timerState=ACTIVE info=Timer created at 2024-05-28T10:49:18.715560], info: Timer created at 2024-05-28T10:49:18.715560, class: class org.jboss.as.ejb3.timerservice.TimerImpl
2024-05-28 10:50:12,300 INFO  [org.jboss.playground.ejb.TestTimer] (ServerService Thread Pool -- 28) INIT: Timertest: 10000 ( 0 min)
2024-05-28 10:50:12,328 ERROR [org.jboss.as.ejb3.timer] (EJB default - 1) WFLYEJB0020: Error invoking timeout for timer: [id=d5c139d8-8bd9-4fd8-bd17-fb7686af2f16 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=2024-05-28 10:49:50.0 initialExpiration=2024-05-28 10:49:20.0 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 10:50:20 CEST 2024 timerState=CANCELED info=Timer created at 2024-05-28T10:49:18.715560]: jakarta.ejb.NoSuchObjectLocalException: WFLYEJB0331: Timer d5c139d8-8bd9-4fd8-bd17-fb7686af2f16 was canceled
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.spi.ManagedTimer.validateInvocationContext(ManagedTimer.java:66)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimerImpl.getInfo(TimerImpl.java:189)
	at deployment.playground.war//org.jboss.playground.ejb.TestTimer.programmaticTimeout(TestTimer.java:75)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:35)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:50)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:44)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.delegateInterception(Jsr299BindingsInterceptor.java:62)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.doMethodInterception(Jsr299BindingsInterceptor.java:72)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:87)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:44)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:50)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:44)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:26)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:28)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:35)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:36)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:39)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:237)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:373)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:143)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.weld.core@5.1.2.Final//org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:87)
	at org.jboss.as.weld.common@32.0.0.Final//org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:72)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:24)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.security.IdentityOutflowInterceptor.processInvocation(IdentityOutflowInterceptor.java:56)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.security.SecurityDomainInterceptor.processInvocation(SecurityDomainInterceptor.java:27)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.singleton.ContainerManagedConcurrencyInterceptor.processInvocation(ContainerManagedConcurrencyInterceptor.java:89)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:47)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.as.ee@32.0.0.Final//org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:33)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
	at org.wildfly.security.elytron-base@2.4.1.Final//org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:633)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
	at org.jboss.invocation@2.0.1.Final//org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.invoke(TimedObjectInvokerImpl.java:85)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:63)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.spi.TimedObjectInvoker.callTimeout(TimedObjectInvoker.java:43)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimerTask.invokeBeanMethod(TimerTask.java:199)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimerTask.callTimeout(TimerTask.java:195)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimerTask.run(TimerTask.java:169)
	at org.jboss.as.ejb3@32.0.0.Final//org.jboss.as.ejb3.timerservice.TimerServiceImpl$Task$1.run(TimerServiceImpl.java:991)
	at org.wildfly.extension.request-controller@24.0.0.Final//org.wildfly.extension.requestcontroller.ControlPointTask.run(ControlPointTask.java:29)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1990)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
	at java.base/java.lang.Thread.run(Thread.java:829)
	at org.jboss.threads@2.4.0.Final//org.jboss.threads.JBossThread.run(JBossThread.java:513)

2024-05-28 10:50:12,329 INFO  [org.jboss.as.ejb3.timer] (EJB default - 1) WFLYEJB0021: Timer: [id=d5c139d8-8bd9-4fd8-bd17-fb7686af2f16 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=2024-05-28 10:49:50.0 initialExpiration=2024-05-28 10:49:20.0 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 10:50:20 CEST 2024 timerState=CANCELED info=Timer created at 2024-05-28T10:49:18.715560] will be retried
2024-05-28 10:50:12,330 INFO  [org.jboss.as.ejb3.timer] (EJB default - 1) WFLYEJB0024: Timer is not active, skipping retry of timer: [id=d5c139d8-8bd9-4fd8-bd17-fb7686af2f16 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=2024-05-28 10:49:50.0 initialExpiration=2024-05-28 10:49:20.0 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 10:50:20 CEST 2024 timerState=CANCELED info=Timer created at 2024-05-28T10:49:18.715560]
2024-05-28 10:50:12,332 WARN  [org.jboss.playground.ContextListener] (ServerService Thread Pool -- 28) ServletContextListener - context initialized at 1716886212332, ServerInfo: WildFly Full 32.0.0.Final (WildFly Core 24.0.0.Final) - 2.3.13.Final, ContextPath: 
2024-05-28 10:50:12,334 INFO  [jakarta.enterprise.resource.webcontainer.faces.config] (ServerService Thread Pool -- 28) Initializing Mojarra 4.0.7 for context ''
2024-05-28 10:50:12,358 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 28) WFLYUT0021: Registered web context: '/' for server 'default-server'
2024-05-28 10:50:12,382 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 79) WFLYSRV0010: Deployed "playground.war" (runtime-name : "playground.war")
2024-05-28 10:50:14,332 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) Timer: id: [id=9844e39e-f923-4222-b420-48d2f14e95f9 timedObjectId=playground.playground.TestTimer auto-timer?:false persistent?:true timerService=TimerServiceImpl(playground.playground.TestTimer) previousRun=Tue May 28 10:50:14 CEST 2024 initialExpiration=Tue May 28 10:50:14 CEST 2024 intervalDuration(in milli sec)=10000 nextExpiration=Tue May 28 10:50:24 CEST 2024 timerState=IN_TIMEOUT info=Timer created at 2024-05-28T10:50:12.300396], info: Timer created at 2024-05-28T10:50:12.300396, class: class org.jboss.as.ejb3.timerservice.TimerImpl
2024-05-28 10:50:14,332 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) START: Timer created at 2024-05-28T10:50:12.300396 Persistent: true
2024-05-28 10:50:14,333 INFO  [org.jboss.playground.ejb.TestTimer] (EJB default - 1) END: Timer created at 2024-05-28T10:50:12.300396

              pferraro@redhat.com Paul Ferraro
              rhn-support-jbaesner Joerg Baesner
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

                Created:
                Updated:
                Resolved: