Document initialization and shutdown logging semantics for the TestContext framework

[asaikali]

Current Behavior

The default logging configuration for Spring Boot is to send logs to the console. Info logs are printed at application context startup and via shutdown hook when the application context is shutting down. Due to the way that test runners in gradle, intellj, and other tools capture console for tests we end up with stray output.

> Task :components:database:test
2020-07-12 09:54:24.952  INFO 46723 --- [extShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2020-07-12 09:54:24.954  INFO 46723 --- [extShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Shutting down ExecutorService 'applicationTaskExecutor'
2020-07-12 09:54:24.955  INFO 46723 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2020-07-12 09:54:25.402  INFO 46723 --- [extShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.

You can see a detailed discussion on this at Gradle Issue 12423 and a project to reproduce the issue. I am working on a multi module project and I end up with a lot of shutdown hook noise in my console every time I run ./gradlew build. Ideally there is no shutdown hook output displayed to the screen.

Why this problem occurs

Test runners want to associate the execution of a test with the console output of that test. Lets say you have a method such as

@Test 
void testSomething(){
  // given
  // when 
  System.out.println("Hello");
 // then 
}

The test runners want to generate a report that can display the console output that was generated when the testSomething method was executing. When there are multiple threads present things become unpredictable if there is a test executing whatever threads on the JVM print to the console gets associated with that test. Consider the screenshot below.

The test case being executed does not not actually print any output , the output captured is from the spring initialization code running on what appears to be a test containers, this happens to be an integration test against a PostgreSQL database launched via test containers project.

According to a post from Luke Daly from the gradle team when there are multiple threads.

Gradle captures the output during tests, and associates it with the test case. Within a shutdown hook, there’s no test case to associate it with and nowhere else to send it other than to “the console”. This is the safest default as that output might be useful information, and there’s no other way to capture it.

So the observed behavior is not a bug in Gradle or Spring, but it is caused by the interaction between the default behaviors of spring and Gradle. BTW I see the same issue when running tests in intelliJ the output that intellij associates with each of the test case methods is somewhat random due to thread timing issues.

Workaround 1

One option is to turn off console logging in SpringBoot by setting

logging:
  level:
    root: error

this works no more shutdown hook info output. When a test class marked up with @SpringBootTest runs it is quite useful to be able to inspect the console and see what version of boot is running, how long things took any useful info messages. Therefore this workaround is not desirable. The current of state of initalization and shutdown output being associated with random @Test methods is also undesirable.

Workaround 2
I created a logback-spring.xml file and used it to direct logs from test executions to a log file, using profiles and the log file below.

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">
  <springProfile name="test">
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <property name="LOG_FILE" value="build/logs/spring-tests.log"/>
    <include resource="org/springframework/boot/logging/logback/file-appender.xml"/>
    <root level="INFO">
      <appender-ref ref="FILE"/>
    </root>
  </springProfile>

  <springProfile name="!test">
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>
    <root level="INFO">
      <appender-ref ref="CONSOLE"/>
    </root>
  </springProfile>
</configuration>

The disadvantage of this workaround is that intelliJ Junit runner no longer displays any of the startup up/shutdown output I have to go to build/logs to get it.

Desired Behavior

The workarounds are not ideal would be nice if there was a way to auto configure this type of setup or at the very least explain this issue in the docs.

[wilkinsona]

Thanks for the suggestion. Unfortunately, I don't think there's anything that we can do about this in Spring Boot as it's a natural consequence of how Spring Framework's test framework creates and destroys application contexts.

When a test class is being run, the test framework creates the application context for the class's tests. This happens before any of the class's tests are run. If this output is being associated with a particular test, then that sounds like a bug in how the output is captured and associated. IMO, it should be associated with the initialisation of the test class rather than any of its tests.

Once the test framework has created an application context, it caches this context for subsequent reuse. Once all of the tests have been executed and the JVM is exiting, the cached contexts are closed. This output isn't associated with any particular test or even test class and, IMO, that's the correct behaviour as the same context may have been shared by many tests spread across multiple test classes.

You could avoid the output caused by the contexts being closed when the JVM is shutting down by disabling context caching in the test framework. @DirtiesContext is one way to do that. Setting the spring.test.context.cache.maxSize system property to 0 is another. However, this will slow your tests down if they were previously able to share contexts between test classes.

As you'd said yourself, neither using error logging nor logging to a file is ideal so I don't think it makes sense for Boot to automatically configure either of those options. If this is going to be addressed at all, I think it should be done in Spring Framework. For example, the effect on logging could be mentioned in this section alongside the existing note about forked processes.

[sbrannen]

I agree with @wilkinsona's assessment: it is essentially the "nature of the beast", and I don't think there is really anything we should be doing in Spring Framework to change this behavior.

Though, as Andy pointed out, it could certainly be documented in the reference manual.

As a side note, it should be possible to implement a Logback filter that excludes log events submitted for the thread named SpringContextShutdownHook (which correlates to the shortened [extShutdownHook] element you see in your log statements), but I'm not convinced that Spring Framework or Spring Boot should publish such a customized logging filter for a particular logging framework.

In light of that, let's turn this into a documentation issue for the "Testing" chapter in the Spring Framework reference manual.

[asaikali]

@sbrannen does junit5 own the correlation of test output to test method execution or is that done by tools such as gradle, maven, intelrij ... etc? could this be something handled by junit where there is the concept of output that is related to the execution of a test class rather than a specific test method?

[sbrannen]

does junit5 own the correlation of test output to test method execution or is that done by tools such as gradle, maven, intelrij ... etc?

The JUnit Platform does provide support for Capturing Standard Output/Error; however, that is an opt-in feature, and it is still up to the tool or IDE running the tests to determine what to do with those report entries.

As stated in the documentation linked above:

Please note that the captured output will only contain output emitted by the thread that was used to execute a container or test. Any output by other threads will be omitted because particularly when executing tests in parallel it would be impossible to attribute it to a specific test or container.