Basically my issue is described in #32381. The implemented solution works in almost all cases, but I still experience TaskRejectedException
logged as errors in the following case:
* application context is stopping;
* ContextClosedEvent
is already published;
* SimpleAsyncTaskScheduler#scheduledExecutor
is shut down, but didn't yet terminated;
I couldn't create a minimal reproducible example, but I'd like to show an excerpt from logs.
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [cheduling-19424] c.c.MyTaskBean : Task working
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.b.a.ApplicationAvailabilityBean : Application availability state ReadinessState changed from ACCEPTING_TRAFFIC to REFUSING_TRAFFIC
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [ionShutdownHook] ConfigServletWebServerApplicationContext : Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@28a2a3e7, started on Wed Aug 07 09:59:00 CEST 2024
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [cheduling-19425] c.c.MyTaskBean : Task working
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [cheduling-19426] c.c.MyTaskBean : Task working
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [cheduling-19427] c.c.MyTaskBean : Task working
2024-08-07T09:59:05.977+02:00 DEBUG 65937 --- [cheduling-19428] c.c.MyTaskBean : Task working
2024-08-07T09:59:05.977+02:00 ERROR 65937 --- [cheduling-19428] o.s.s.s.TaskUtils$LoggingErrorHandler : Unexpected error occurred in scheduled task
org.springframework.core.task.TaskRejectedException: ExecutorService in shutdown state did not accept task: com.company.MyTaskBean$$Lambda/0x000003ff01a10ed0@3c00151f
at org.springframework.scheduling.concurrent.SimpleAsyncTaskScheduler.schedule(SimpleAsyncTaskScheduler.java:234)
at com.company.MyTaskBean.task(MyTaskBean.kt:87)
at com.company.MyTaskBean.task$lambda$1(MyTaskBean.kt:87)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at java.base/java.lang.VirtualThread.run(VirtualThread.java:329)
Caused by: java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@93d3468[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@74f27d38[Wrapped task = org.springframework.scheduling.concurrent.SimpleAsyncTaskScheduler$$Lambda/0x000003ff019a8f70@53630565]] rejected from org.springframework.scheduling.concurrent.SimpleAsyncTaskScheduler$1@1d884a19[Shutting down, pool size = 1, active threads = 0, queued tasks = 2, completed tasks = 19427]
at java.base/java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2081)
at java.base/java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:841)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:340)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:562)
at org.springframework.scheduling.concurrent.SimpleAsyncTaskScheduler.schedule(SimpleAsyncTaskScheduler.java:231)
... 4 common frames omitted
2024-08-07T09:59:05.978+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147483647
2024-08-07T09:59:05.978+02:00 TRACE 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Asking bean 'taskScheduler' of type [org.springframework.scheduling.concurrent.SimpleAsyncTaskScheduler] to stop
2024-08-07T09:59:05.978+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'taskScheduler' completed its stop procedure
2024-08-07T09:59:05.978+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147482623
2024-08-07T09:59:05.978+02:00 TRACE 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Asking bean 'webServerGracefulShutdown' of type [org.springframework.boot.web.context.WebServerGracefulShutdownLifecycle] to stop
2024-08-07T09:59:05.979+02:00 INFO 65937 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown : Commencing graceful shutdown. Waiting for active requests to complete
2024-08-07T09:59:05.980+02:00 INFO 65937 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown : Graceful shutdown complete
2024-08-07T09:59:05.980+02:00 DEBUG 65937 --- [tomcat-shutdown] o.s.c.support.DefaultLifecycleProcessor : Bean 'webServerGracefulShutdown' completed its stop procedure
2024-08-07T09:59:05.981+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase 2147481599
2024-08-07T09:59:05.981+02:00 TRACE 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Asking bean 'webServerStartStop' of type [org.springframework.boot.web.servlet.context.WebServerStartStopLifecycle] to stop
2024-08-07T09:59:05.981+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'webServerStartStop' completed its stop procedure
2024-08-07T09:59:05.981+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Stopping beans in phase -2147483647
2024-08-07T09:59:05.981+02:00 TRACE 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Asking bean 'springBootLoggingLifecycle' of type [org.springframework.boot.context.logging.LoggingApplicationListener$Lifecycle] to stop
2024-08-07T09:59:05.981+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor : Bean 'springBootLoggingLifecycle' completed its stop procedure
2024-08-07T09:59:05.982+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.s.c.ThreadPoolTaskScheduler : Shutting down ExecutorService
2024-08-07T09:59:05.985+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.j.e.a.AnnotationMBeanExporter : Unregistering JMX-exposed beans on shutdown
2024-08-07T09:59:05.985+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.j.e.a.AnnotationMBeanExporter : Unregistering JMX-exposed beans
2024-08-07T09:59:05.986+02:00 INFO 65937 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : read-only - Shutdown initiated...
2024-08-07T09:59:05.988+02:00 INFO 65937 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : read-only - Shutdown completed.
2024-08-07T09:59:05.988+02:00 INFO 65937 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : read-write - Shutdown initiated...
2024-08-07T09:59:05.989+02:00 INFO 65937 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource : read-write - Shutdown completed.
2024-08-07T09:59:05.989+02:00 DEBUG 65937 --- [ionShutdownHook] o.s.b.f.support.DisposableBeanAdapter : Custom destroy method 'close' on bean with name 'simpleclientPrometheusMeterRegistry' completed
I suppose, the reason can be explained as follows.
* SimpleAsyncTaskScheduler#onApplicationEvent
calls ExecutorService#shutdown
thus switching its running state to SHUTDOWN
.
* SimpleAsyncTaskScheduler#shutdownAwareErrorHandler
checks for ExecutorService#isTerminated
which only returns true
if an executor is in TERMINATED
running state.
The proposed solution: use ExecutorService#isShutdown
instead.
I hesitated to create a PR as I also found a call to isTerminated
to ExecutorLifecycleDelegate
and not sure if it should be changed too.
Comment From: simonbasle
Thanks for the detailed analysis @genuss. I think what you propose for SimpleAsyncTaskScheduler#shutdownAwareErrorHandler
makes sense. The ExecutorLifecycleDelegate
should be reviewed separately though.
Comment From: genuss
Should I create a PR for the change?
Comment From: simonbasle
@genuss if you have something ready, please go ahead :)
Comment From: jhoeller
Sounds sensible to use isShutdown()
there, suppressing the log entry even before full termination there.
As for ExecutorLifecycleDelegate
, the use of isTerminated()
seems correct there since isRunning()
is expected to return true
up until actual termination.
Comment From: jhoeller
Superseded by PR #33336.