How to end spring @Schedule task gracefully?

Question

I'm trying to get a spring boot service to end gracefully.It has a method with a @Scheduled annotation. The service uses spring-data for the DB and spring-cloud-stream for RabbitMQ. It's vital that the DB and RabbitMQ are accessible until the scheduled method ends. There's an autoscaler in place which frequently starts/stops service instances, crashing while stopping is not an option.

From this post Spring - Scheduled Task - Graceful Shutdown I take that it should be enough to add

    @Bean
    TaskSchedulerCustomizer taskSchedulerCustomizer() {
        return taskScheduler -> {
            taskScheduler.setWaitForTasksToCompleteOnShutdown(true);
            taskScheduler.setAwaitTerminationSeconds(30);
        };
    }

and spring should wait to shut down the application until the scheduled method has finished or 30s have expired.

When the service is stopped while the scheduled method is executed I can see the following things from the log

spring-cloud-stream is closing the connections without waiting for the method to finish.
spring-data is also closing the db-connection right away.
The method is not stopped and tries to finish but fails since it cannot access the Db anymore.

Any ideas how to get the scheduled method including db-connection and rabbitMq access to finish gracefully?

This is my application class:

@SpringBootApplication(scanBasePackages = {
    "xx.yyy.infop.dao",
    "xx.yyy.infop.compress"})
@EntityScan("ch.sbb.infop.common.entity")
@EnableJpaRepositories({"xx.yyy.infop.dao", "xx.yyy.infop.compress.repository"})
@EnableBinding(CompressSink.class)
@EnableScheduling
public class ApplicationCompress {

    @Value("${max.commpress.timout.seconds:300}")
    private int maxCompressTimeoutSeconds;

    public static void main(String[] args) {
        SpringApplication.run(ApplicationCompress.class, args);
    }

    @Bean
    TaskSchedulerCustomizer taskSchedulerCustomizer() {
        return taskScheduler -> {
            taskScheduler.setWaitForTasksToCompleteOnShutdown(true);
            taskScheduler.setAwaitTerminationSeconds(maxCompressTimeoutSeconds);
        };
    }

}

And this the bean:

@Component
@Profile("!integration-test")
public class CommandReader {

    private static final Logger LOGGER = LoggerFactory.getLogger(CommandReader.class);

    private final CompressSink compressSink;
    private final CommandExecutor commandExecutor;

    CommandReader(CompressSink compressSink, CommandExecutor commandExecutor) {
        this.compressSink = compressSink;
        this.commandExecutor = commandExecutor;
    }

    @PreDestroy
    private void preDestory() {
        LOGGER.info("preDestory");
    }

    @Scheduled(fixedDelay = 1000)
    public void poll() {
        LOGGER.debug("Start polling.");
        ParameterizedTypeReference<CompressCommand> parameterizedTypeReference = new ParameterizedTypeReference<>() {
        };
        if (!compressSink.inputSync().poll(this::execute, parameterizedTypeReference)) {
            compressSink.inputAsync().poll(this::execute, parameterizedTypeReference);
        }
        LOGGER.debug("Finished polling.");
    }

    private void execute(Message<?> message) {
        CompressCommand compressCommand = (CompressCommand) message.getPayload();

        // uses spring-data to write to DB
        CompressResponse compressResponse = commandExecutor.execute(compressCommand);

        // Schreibt die Anwort in Rensponse-Queue
        compressSink.outputResponse().send(MessageBuilder.withPayload(compressResponse).build());
    }

}

And here some lines from the log (see https://pastebin.com/raw/PmmqhH1P for the full log):

2020-05-15 11:59:35,640 [restartedMain] - INFO org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler.initialize - traceid= - Initializing ExecutorService 'taskScheduler'

2020-05-15 11:59:44,976 [restartedMain] - INFO org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.initialize - traceid= - Initializing ExecutorService 'applicationTaskExecutor'

Disconnected from the target VM, address: '127.0.0.1:52748', transport: 'socket'
2020-05-15 12:00:01,228 [SpringContextShutdownHook] - INFO org.springframework.cloud.stream.binder.BinderErrorChannel.adjustCounterIfNecessary - traceid= - Channel 'application-1.kompressSync.komprimierungSyncProcessingGroup.errors' has 1 subscriber(s).
2020-05-15 12:00:01,229 [SpringContextShutdownHook] - INFO org.springframework.cloud.stream.binder.BinderErrorChannel.adjustCounterIfNecessary - traceid= - Channel 'application-1.kompressSync.komprimierungSyncProcessingGroup.errors' has 0 subscriber(s).
2020-05-15 12:00:01,232 [SpringContextShutdownHook] - INFO org.springframework.cloud.stream.binder.BinderErrorChannel.adjustCounterIfNecessary - traceid= - Channel 'application-1.kompressAsync.komprimierungAsyncProcessingGroup.errors' has 1 subscriber(s).
2020-05-15 12:00:01,232 [SpringContextShutdownHook] - INFO org.springframework.cloud.stream.binder.BinderErrorChannel.adjustCounterIfNecessary - traceid= - Channel 'application-1.kompressAsync.komprimierungAsyncProcessingGroup.errors' has 0 subscriber(s).
2020-05-15 12:00:01,237 [SpringContextShutdownHook] - INFO org.springframework.integration.endpoint.EventDrivenConsumer.logComponentSubscriptionEvent - traceid= - Removing {logging-channel-adapter:_org.springframework.integration.errorLogger} as a subscriber to the 'errorChannel' channel
2020-05-15 12:00:01,237 [SpringContextShutdownHook] - INFO org.springframework.integration.channel.PublishSubscribeChannel.adjustCounterIfNecessary - traceid= - Channel 'application-1.errorChannel' has 0 subscriber(s).
2020-05-15 12:00:01,237 [SpringContextShutdownHook] - INFO org.springframework.integration.endpoint.EventDrivenConsumer.stop - traceid= - stopped bean '_org.springframework.integration.errorLogger'
2020-05-15 12:00:01,244 [SpringContextShutdownHook] - INFO org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor.shutdown - traceid= - Shutting down ExecutorService 'applicationTaskExecutor'
2020-05-15 12:00:01,245 [SpringContextShutdownHook] - INFO yy.xxx.infop.compress.CommandReader.preDestory - traceid= - preDestory
2020-05-15 12:00:01,251 [SpringContextShutdownHook] - INFO org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.destroy - traceid= - Closing JPA EntityManagerFactory for persistence unit 'default'
2020-05-15 12:00:01,256 [SpringContextShutdownHook] - INFO org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler.shutdown - traceid= - Shutting down ExecutorService 'taskScheduler'
2020-05-15 12:00:01,256 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - 4
2020-05-15 12:00:02,257 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - 5
2020-05-15 12:00:03,258 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - 6
2020-05-15 12:00:04,260 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - 7
2020-05-15 12:00:05,260 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - 8
2020-05-15 12:00:06,261 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - 9
2020-05-15 12:00:07,262 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.doInTransactionWithoutResult - traceid=d22b696edc90e123 - end
2020-05-15 12:00:07,263 [scheduling-1] - INFO yy.xxx.infop.compress.condense.VmLaufVerdichter.verdichte - traceid=d22b696edc90e123 - VarianteTyp=G, vmId=482392382, vnNr=8416
2020-05-15 12:00:07,326 [scheduling-1] -ERROR yy.xxx.infop.compress.CommandExecutor.execute - traceid=d22b696edc90e123 - 

org.springframework.beans.factory.BeanCreationNotAllowedException: Error creating bean with name 'inMemoryDatabaseShutdownExecutor': Singleton bean creation not allowed while singletons of this factory are in destruction (Do not request a bean from a BeanFactory in a destroy method implementation!)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:208) ~[spring-beans-5.2.4.RELEASE.jar:5.2.4.RELEASE]

2020-05-15 12:00:08,332 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.execute - traceid=d22b696edc90e123 - Compress started. compressCommand=yy.xxx.infop.compress.client.CompressCommand@247ec0d[hostName=K57176,jobId=b1211ee8-4a54-47f2-a58b-92b3560bbddd,cmdId=1,userId=goofy2,commandTyp=verdichtet G, T und komprimiert G, T,vmId=482392382,started=1589536752609]
2020-05-15 12:00:08,337 [scheduling-1] -ERROR yy.xxx.infop.compress.CommandExecutor.execute - traceid=d22b696edc90e123 - 

org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is java.lang.IllegalStateException: EntityManagerFactory is closed
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:448) ~[spring-orm-5.2.4.RELEASE.jar:5.2.4.RELEASE]

2020-05-15 12:00:10,339 [scheduling-1] - INFO yy.xxx.infop.compress.CommandExecutor.execute - traceid=d22b696edc90e123 - Compress started. compressCommand=yy.xxx.infop.compress.client.CompressCommand@247ec0d[hostName=K57176,jobId=b1211ee8-4a54-47f2-a58b-92b3560bbddd,cmdId=1,userId=goofy2,commandTyp=verdichtet G, T und komprimiert G, T,vmId=482392382,started=1589536752609]
2020-05-15 12:00:10,343 [scheduling-1] -ERROR yy.xxx.infop.compress.CommandExecutor.execute - traceid=d22b696edc90e123 - 

org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is java.lang.IllegalStateException: EntityManagerFactory is closed

2020-05-15 12:00:10,351 [scheduling-1] -DEBUG yy.xxx.infop.compress.CommandReader.poll - traceid=d22b696edc90e123 - Finished polling.
2020-05-15 12:00:10,372 [SpringContextShutdownHook] - INFO org.springframework.integration.monitor.IntegrationMBeanExporter.destroy - traceid= - Summary on shutdown: bean 'response'
2020-05-15 12:00:10,372 [SpringContextShutdownHook] - INFO org.springframework.integration.monitor.IntegrationMBeanExporter.destroy - traceid= - Summary on shutdown: nullChannel
2020-05-15 12:00:10,373 [SpringContextShutdownHook] - INFO org.springframework.integration.monitor.IntegrationMBeanExporter.destroy - traceid= - Summary on shutdown: bean 'errorChannel'
2020-05-15 12:00:10,373 [SpringContextShutdownHook] - INFO org.springframework.integration.monitor.IntegrationMBeanExporter.destroy - traceid= - Summary on shutdown: bean '_org.springframework.integration.errorLogger.handler' for component '_org.springframework.integration.errorLogger'
2020-05-15 12:00:10,374 [SpringContextShutdownHook] - INFO com.zaxxer.hikari.HikariDataSource.close - traceid= - HikariPool-1 - Shutdown initiated...
2020-05-15 12:00:10,405 [SpringContextShutdownHook] - INFO com.zaxxer.hikari.HikariDataSource.close - traceid= - HikariPool-1 - Shutdown completed.

Process finished with exit code 130

"*crashing while stopping is not an option*" You cannot enforce this. Any number of things could happen. What if the power goes down, for example? — Michael, May 15 '20 at 10:37
Yes, of course. I'm talking about a normal shutdown, where the shutdown hooks of spring should make sure things are shutdown in a friendly manner. — BetaRide, May 15 '20 at 12:30
If you are using AWS' autoscaler, it will send SIGKILL to your VM before it scales down the app and shuts down the JVM. Maybe add a [shutdown hook](https://stackoverflow.com/questions/1611931/catching-ctrlc-in-java) to the program? — Brad, Dec 26 '20 at 17:30

score 2 · Answer 1 · answered Dec 26 '20 at 17:24

I've tested this configuration which should do the same as your TaskSchedulerCustomizer:

spring.task.scheduling.shutdown.await-termination=true
spring.task.scheduling.shutdown.await-termination-period=30s

Spring waits 30 seconds with all services available before shutting down anything if there are active tasks. If there are no active tasks, the shutdown is immediate.

It is worth mentioning that what brought me to this question was the graceful shutdown of @Async methods which is configured in a very similar way:

spring.task.execution.shutdown.await-termination=true
spring.task.execution.shutdown.await-termination-period=1s

or in code:

@Bean
public TaskExecutorCustomizer taskExecutorCustomizer() {
    // Applies to @Async tasks, not @Scheduled as in the question
    return (customizer) -> {
        customizer.setWaitForTasksToCompleteOnShutdown(true);
        customizer.setAwaitTerminationSeconds(10);
    };
}

Back to your case, my guess is that the TaskSchedulerCustomizer is not actually executed or is overridden by something else after it executes.

For the first option, validate by adding logging statements or setting a breakpoint in taskSchedulerCustomizer().

For the second option, I suggest setting a breakpoint in TaskSchedulerBuilder::configure() to see what happens. Once the debugger breaks in that method, add a data breakpoint on the ExecutorConfigurationSupport::awaitTerminationMillis property of the taskScheduler to see if that property is modified elsewhere.

You can see the final termination period used in the shutdown process in the method ExecutorConfigurationSupport::awaitTerminationIfNecessary.

How to end spring @Schedule task gracefully?

1 Answers1