quarkus scheduler does not await termination of scheduledExecutor #16833
Closed
Description
Describe the bug
I execute the following code inspired from https://quarkus.io/guides/scheduler:
@ApplicationScoped
public class MyTimer {
public static Logger log = Logger.getLogger(MyTimer.class);
private final String start = new Date().toString();
private final AtomicInteger count = new AtomicInteger();
@Scheduled(every = "10S")
public void run() {
for (int i = 0; i < 10; i++) {
log.info("execute " + start + " => " + count.incrementAndGet());
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
log.error("timer interrupted", e);
break;
}
}
}
}
When hot code replace happens in dev mode, the scheduler extension does not wait for the scheduledExecutor to terminate.
as a result, the old timer continues executing the tasks that are in progress in parallel with the new tasks scheduler by the new timer.
Eventually, the old code finishes up, and only the new timer remains.
For instance, here is how it looks like with the previous example:
...
2021-04-27 14:29:32,002 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:17 CEST 2021 => 16
2021-04-27 14:29:33,003 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:17 CEST 2021 => 17
2021-04-27 14:29:34,004 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:17 CEST 2021 => 18
2021-04-27 14:29:35,004 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:17 CEST 2021 => 19
2021-04-27 14:29:36,005 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:17 CEST 2021 => 20
2021-04-27 14:29:37,000 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 21
2021-04-27 14:29:38,000 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 22
2021-04-27 14:29:39,001 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 23
2021-04-27 14:29:40,001 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 24
2021-04-27 14:29:41,002 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 25
2021-04-27 14:29:42,002 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 26
2021-04-27 14:29:42,509 INFO [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-10) File change detected: E:\tmp\quarkus\test_timer\getting-started\src\main\resources\application.properties
2021-04-27 14:29:42,540 INFO [io.quarkus] (Quarkus Main Thread) getting-started stopped in 0.027s
2021-04-27 14:29:43,003 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 27
__ ____ __ _____ ___ __ ____ ______
--/ __ \/ / / / _ | / _ \/ //_/ / / / __/
-/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2021-04-27 14:29:43,859 INFO [io.quarkus] (Quarkus Main Thread) getting-started 1.0.0-SNAPSHOT on JVM (powered by Quarkus 1.13.2.Final) started in 1.315s. Listening on: http://localhost:8081
2021-04-27 14:29:43,860 INFO [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2021-04-27 14:29:43,860 INFO [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, resteasy, scheduler]
2021-04-27 14:29:43,865 INFO [io.qua.dep.dev.RuntimeUpdatesProcessor] (vert.x-worker-thread-10) Hot replace total time: 1.366s
2021-04-27 14:29:44,002 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:44 CEST 2021 => 1
2021-04-27 14:29:44,004 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 28
2021-04-27 14:29:45,010 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:44 CEST 2021 => 2
2021-04-27 14:29:45,011 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 29
2021-04-27 14:29:46,010 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:44 CEST 2021 => 3
2021-04-27 14:29:46,011 INFO [org.acm.get.sta.MyTimer] (executor-thread-198) execute Tue Apr 27 14:29:17 CEST 2021 => 30
2021-04-27 14:29:47,011 INFO [org.acm.get.sta.MyTimer] (executor-thread-1) execute Tue Apr 27 14:29:44 CEST 2021 => 4
2021-04-27 14:29:47,012 ERROR [io.qua.sch.run.SimpleScheduler] (executor-thread-198) Error occured while executing task for trigger IntervalTrigger [id=1_org.acme.getting.started.MyTimer_ScheduledInvoker_run_72e66771a77415a7284d3ae42331659c186071de, interval=10000]:
javax.enterprise.context.ContextNotActiveException
at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:40)
at io.quarkus.arc.runtime.devconsole.InvocationTree_ClientProxy.arc$delegate(InvocationTree_ClientProxy.zig:42)
at io.quarkus.arc.runtime.devconsole.InvocationTree_ClientProxy.invocationCompleted(InvocationTree_ClientProxy.zig:128)
at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:74)
at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(InvocationInterceptor_Bean.zig:521)
at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
at org.acme.getting.started.MyTimer_Subclass.run(MyTimer_Subclass.zig:147)
at org.acme.getting.started.MyTimer_ClientProxy.run(MyTimer_ClientProxy.zig:126)
at org.acme.getting.started.MyTimer_ScheduledInvoker_run_72e66771a77415a7284d3ae42331659c186071de.invokeBean(MyTimer_ScheduledInvoker_run_72e66771a77415a7284d3ae42331659c186071de.zig:46)
at io.quarkus.arc.runtime.BeanInvoker.invoke(BeanInvoker.java:20)
at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$1.run(SimpleScheduler.java:204)
at io.quarkus.runtime.CleanableExecutor$CleaningRunnable.run(CleanableExecutor.java:231)
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.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2415)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
at java.base/java.lang.Thread.run(Thread.java:834)
at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Note that this behavior is less visible, but happens also in production mode: in Graceful shutdown, we should also wait for the termination of tasks that are in progress.
I think here is the relevant code.
Expected behavior
Stopping the timer, awaiting termination, then restart the application.
Actual behavior
Old timers keep running until they finish up normally.
If we do not await termination, another option would be to interrupt the threads.
To Reproduce
Link to a small reproducer (preferably a Maven project if the issue is not Gradle-specific).
Execute the above code in a scheduler application
Configuration
# Add your application.properties here, if applicable.
Screenshots
(If applicable, add screenshots to help explain your problem.)
Environment (please complete the following information):
Output of uname -a or ver
Output of java -version
GraalVM version (if different from Java)
Quarkus version or git rev
Quarkus 1.13.2.Final
Build tool (ie. output of mvnw --version or gradlew --version)
Additional context
(Add any other context about the problem here.)