In my Kotlin project, the logging shutdown hook doesn't seem to be registered in the tests as of Spring Boot 2.5.1. In 2.5.0, it behaves correctly.

At the end of the tests in my Gradle build, JPA/Hikari messages are logged to the console.

In 2.4.10, the solution was to set the property logging.register-shutdown-hook=true. In 2.5.x, that property is true by default. In 2.5.0, I can remove the property from application.yaml and it behaves correctly, that is, the messages are not logged. In 2.5.1 - 2.5.4, the messages are logged again, no matter if I add the property or not.

The project can be found here: https://github.com/igorakkerman/springboot-kotlin-demo

This is the Gradle output in 2.5.4:

> Task :test
2021-09-23 00:16:09.317  INFO 13700 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2021-09-23 00:16:09.317  INFO 13700 --- [ionShutdownHook] .SchemaDropperImpl$DelayedDropActionImpl : HHH000477: Starting delayed evictData of schema as part of SessionFactory shut-down'
2021-09-23 00:16:09.319 DEBUG 13700 --- [ionShutdownHook] org.hibernate.SQL                        :

    drop table if exists computer CASCADE
2021-09-23 00:16:09.326 DEBUG 13700 --- [ionShutdownHook] org.hibernate.SQL                        :

    drop table if exists display CASCADE
2021-09-23 00:16:09.334  INFO 13700 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2021-09-23 00:16:09.334  INFO 13700 --- [ionShutdownHook] .SchemaDropperImpl$DelayedDropActionImpl : HHH000477: Starting delayed evictData of schema as part of SessionFactory shut-down'
2021-09-23 00:16:09.334 DEBUG 13700 --- [ionShutdownHook] org.hibernate.SQL                        :

    drop table if exists computer CASCADE
2021-09-23 00:16:09.336 DEBUG 13700 --- [ionShutdownHook] org.hibernate.SQL                        :

    drop table if exists display CASCADE
2021-09-23 00:16:09.339  INFO 13700 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2021-09-23 00:16:09.345  INFO 13700 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

I noticed that the output in 2.4.10 has the thread ID [extShutdownHook] whereas 2.5.4 has [ionShutdownHook]. Not sure whether this is important or not.

Comment From: wilkinsona

The change in behaviour is intentional. We considered it to be a bug that the shutdown of the application and the shutdown of the logging system could race with each other, potentially losing log messages during shutdown. This was fixed by https://github.com/spring-projects/spring-boot/issues/26660. The logging shutdown hook is still registered, but we now guarantee that the application will be shut down before the logging system, ensuring that any log messages generated during application shutdown are logging.

The behaviour that you were relying on before was never guaranteed. You'd only get the behaviour that you prefer if the shutdown of the logging system won the race against the shutdown of the application. It was also possible for all or, most confusing, only some of the application's logging to be output during shutdown.

We don't want to reinstate the previous, non-deterministic behaviour and, unfortunately, I can't think of a reasonable way to guarantee that the logging system is shut down first without introducing quite a bit of extra complexity. Some of that would be user-facing as we'd need to provide a configuration property that enabled the different behaviour. I think it would only be of interest in tests and only then to a subset of users who, like you, prefer to lose log messages that are output when the test JVM is shutting down.

I don't think we can justify introducing such additional complexity for what I suspect is a niche requirement. I'm going to close this issue for now. We can reconsider if we learn that it's affecting many more users than I am anticipating.

Comment From: igorakkerman

@wilkinsona Thank you very much for explaining the details. As far as I understand, what's happening in this very order is: 1. the application (JUnit) terminates 2. the Gradle test task stops controlling the standard output 3. the application shutdown hook kicks in and logs its events (the console output that I'm getting) 4. the logging shutdown hook shuts down the logging system

Whereas previously, steps 3 and 4 were inverted (most of the time but non-deterministically), that is, the order was 1,2,4,3. Can you please confirm whether I got this correctly?

If this is the case, I believe it is an issue on Gradle's side and they should make sure that the output of the application shutdown hook goes to the test log, that is into their build/test-results. Probably, otherwise, this information is only ever printed to the console and otherwise lost. https://github.com/gradle/gradle/issues/12423 appears to be about this exact issue.

Comment From: wilkinsona

I don't know exactly when Gradle stops capturing standard output, but I think you've got this correctly.

Thanks for reminding me of gradle/gradle#12423. I knew about it previously due to https://github.com/spring-projects/spring-framework/issues/25385 but it had completely slipped me mind.