How to turn off output from shutdown hooks in gradle boot tests?

Question

You can generate a project from start.spring.io to this issue from https://start.spring.io/starter.zip?type=gradle-project&language=java&bootVersion=2.2.5.RELEASE&baseDir=demo&groupId=com.example&artifactId=demo&name=demo&description=Demo%20project%20for%20Spring%20Boot&packageName=com.example.demo&packaging=jar&javaVersion=1.8&dependencies=h2,data-jpa,web

I have a multi-module springBoot application built with gradle, there are a bunch of SpringBoot integration tests. When I do a build I end up with some output from the SpringBoot shutdown to the console as shown below. How do I turn this output off?

± |master ↑1 {1} S:3 U:10 ✗| → ./gradlew build

> Task :core:test
2020-02-01 11:20:33.529  INFO 24114 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-02-01 11:20:33.531  INFO 24114 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-02-01 11:20:33.538  INFO 24114 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

> Task :email:test
2020-02-01 11:20:43.820  INFO 24150 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-02-01 11:20:43.820  INFO 24150 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-02-01 11:20:43.822  INFO 24150 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-2 - Shutdown initiated...
2020-02-01 11:20:43.822  INFO 24150 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-02-01 11:20:43.830  INFO 24150 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
2020-02-01 11:20:43.830  INFO 24150 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-2 - Shutdown completed.

> Task :security:test
2020-02-01 11:20:54.941  INFO 24188 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-02-01 11:20:54.944  INFO 24188 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-02-01 11:20:54.952  INFO 24188 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

Deprecated Gradle features were used in this build, making it incompatible with Gradle 7.0.
Use '--warning-mode all' to show the individual deprecation warnings.
See https://docs.gradle.org/6.1.1/userguide/command_line_interface.html#sec:command_line_warnings

BUILD SUCCESSFUL in 46s
57 actionable tasks: 54 executed, 3 up-to-date

For reference an application created from start.spring.io with gradle produces no output on the screen

./gradlew build

BUILD SUCCESSFUL in 779ms
5 actionable tasks: 5 up-to-date

Instead the output is placed in build/reports/

In my case I have NOT made any changes to the logging configuration that comes with boot. There is no logback.xml, or changes to the application.yml for logging levels. I am expecting that gradle is capturing the system out and system error and sending them to the build/reports/ but some outputs seems to be escaping to system out.

Answer 1

@eskatos is right. The logging manager is teared down after the test case is executed before the shutting down the worker process. All the shutdown hooks are executed when the worker process is shutdown and are redirected back to console.

As these messages are generated by spring boot the best place would be to filter the shutdown messages using the logback test configuration xml.

Something like logback-test.xml inside src/test/resources

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
            <evaluator> <!-- defaults to type ch.qos.logback.classic.boolex.JaninoEventEvaluator -->
                <expression>return event.getThreadName().contains("ShutdownHook");</expression>
            </evaluator>
            <OnMismatch>NEUTRAL</OnMismatch>
            <OnMatch>DENY</OnMatch>
        </filter>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

build.gradle

testCompile 'org.codehaus.janino:janino'

Answer 2

One can disable the output with TestLoggingContainer testLogging.showStandardStreams = false or decide what to log onOutput of a Test task, in order to control the stdout/stderr of the test JVM:

apply plugin: 'java'

test {

    // show standard out and standard error of the test JVM on the console
    // can be used to disable the console output:
    testLogging.showStandardStreams = true

    // listen to standard out and standard error of the test JVM
    // can be used to make the logging optional:
    onOutput { descriptor, event ->
        logger.lifecycle("Test: " + descriptor + " produced standard out/err: " + event.message)
    }
}

These streams are TestLogEvent STANDARD_OUT & STANDARD_ERROR, which are coming from the JVM. When one can determine an event.message containing extShutdownHook, one can skip the logging.