When running our Java tests with Maven they usually produce a lot of noise in the console. While this log output can help understand test failures, it's typically superfluous when our test suite is passing. Nobody will take a look at the entire output if the tests are green. It's only making the build logs more bloated. A better solution would be to run our tests with Maven silent with no log output and only dump the log output once the tests fail. This blog post demonstrates how to achieve this simple yet convenient technique to run Java tests with Maven silently for a compact and followable build log.
The Status Quo: Noisy Java Tests
Based on our logging configuration, our tests produce quite some log output. When running our entire test suite locally or on a CI server (e.g., GitHub Actions or Jenkins), analyzing a test failure is tedious when there's a lot of noise in the logs. We first have to find our way to the correct position by scrolling or using the search functionality of, e.g., our browser or the integrated terminal of our IDE.
A demo output for a test that verifies email functionality using GreenMail looks like the following:
1 2 | 06:52:17.982 [smtp:127.0.0.1:3025<-/127.0.0.1:53348] INFO c.i.greenmail.user.UserManager - Created user login [email protected] for address [email protected] with password [email protected] because it didn't exist before. 06:52:18.024 [smtp:127.0.0.1:3025<-/127.0.0.1:53350] INFO c.i.greenmail.user.UserManager - Created user login [email protected] for address [email protected] with password [email protected] because it didn't exist before. |
There's usually a lot of default noise of frameworks and test libraries that add up to quite some log output when running an entire test suite:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 | [INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ spring-boot-example --- [INFO] [INFO] ------------------------------------------------------- [INFO] T E S T S [INFO] ------------------------------------------------------- [INFO] Running de.rieckpil.blog.greenmail.MailServiceTest 06:55:24.185 [smtp:127.0.0.1:3025<-/127.0.0.1:53406] INFO c.i.greenmail.user.UserManager - Created user login [email protected] for address [email protected] with password [email protected] because it didn't exist before. 06:55:24.225 [smtp:127.0.0.1:3025<-/127.0.0.1:53408] INFO c.i.greenmail.user.UserManager - Created user login [email protected] for address [email protected] with password [email protected] because it didn't exist before. [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.115 s - in de.rieckpil.blog.greenmail.MailServiceTest [INFO] Running de.rieckpil.blog.junit5.RegistrationWebTest [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 s - in de.rieckpil.blog.junit5.RegistrationWebTest [INFO] Running de.rieckpil.blog.junit5.ExtensionExampleTest Injected random UUID: 6aad64dd-0d22-4681-95ca-d254fa53c3ac Injected random UUID: b3c44f26-7000-4998-9de8-c2b353098e72 Injected random UUID: b75d8d0e-7ac2-4f2c-936c-7d768b7db2cc Injected random UUID: e721908f-a4ef-4938-883d-f2f614534b37 Injected random UUID: e4ead0b5-af7b-40c0-8c9a-459f4ebfcf15 [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.009 s - in de.rieckpil.blog.junit5.ExtensionExampleTest [INFO] Running de.rieckpil.blog.junit5.JUnit5ExampleTest Will run only once before all tests of this class Will run before each test Will run before after each test Will run before each test Will run before after each test Will run before each test Will run before after each test Will run before each test Will run before after each test Will run before each test Will run before after each test Will run only once after all tests of this class [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.022 s - in de.rieckpil.blog.junit5.JUnit5ExampleTest [INFO] Running de.rieckpil.blog.wiremock.WireMockSetupTest 06:55:28.930 [main] INFO org.eclipse.jetty.util.log - Logging initialized @6609ms to org.eclipse.jetty.util.log.Slf4jLog 06:55:28.996 [main] INFO org.eclipse.jetty.server.Server - jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 11.0.11+9-LTS 06:55:29.004 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@5df54296{/__admin,null,AVAILABLE} 06:55:29.005 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@64a7ad02{/,null,AVAILABLE} 06:55:29.010 [main] INFO o.e.jetty.server.AbstractConnector - Started NetworkTrafficServerConnector@20960b51{HTTP/1.1, (http/1.1)}{0.0.0.0:53424} 06:55:29.011 [main] INFO org.eclipse.jetty.server.Server - Started @6690ms 06:55:29.015 [main] INFO o.e.jetty.server.AbstractConnector - Stopped NetworkTrafficServerConnector@20960b51{HTTP/1.1, (http/1.1)}{0.0.0.0:0} 06:55:29.015 [main] INFO o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@64a7ad02{/,null,STOPPED} 06:55:29.015 [main] INFO o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@5df54296{/__admin,null,STOPPED} [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.194 s - in de.rieckpil.blog.wiremock.WireMockSetupTest [INFO] Running de.rieckpil.blog.wiremock.JavaHttpClientTest 06:55:29.019 [main] INFO org.eclipse.jetty.server.Server - jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 11.0.11+9-LTS 06:55:29.020 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@5ff29e8b{/__admin,null,AVAILABLE} 06:55:29.020 [main] INFO o.e.j.server.handler.ContextHandler - Started o.e.j.s.ServletContextHandler@7acfcfc4{/,null,AVAILABLE} 06:55:29.021 [main] INFO o.e.jetty.server.AbstractConnector - Started NetworkTrafficServerConnector@736f8837{HTTP/1.1, (http/1.1)}{0.0.0.0:53425} 06:55:29.021 [main] INFO org.eclipse.jetty.server.Server - Started @6700ms 06:55:29.067 [qtp1974219375-82] INFO o.e.j.s.handler.ContextHandler.ROOT - RequestHandlerClass from context returned com.github.tomakehurst.wiremock.http.StubRequestHandler. Normalized mapped under returned 'null' 06:55:29.087 [qtp1974219375-82] INFO o.e.j.s.h.ContextHandler.__admin - RequestHandlerClass from context returned com.github.tomakehurst.wiremock.http.AdminRequestHandler. Normalized mapped under returned 'null' 06:55:31.189 [main] INFO o.e.jetty.server.AbstractConnector - Stopped NetworkTrafficServerConnector@736f8837{HTTP/1.1, (http/1.1)}{0.0.0.0:0} 06:55:31.189 [main] INFO o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@7acfcfc4{/,null,STOPPED} 06:55:31.189 [main] INFO o.e.j.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@5ff29e8b{/__admin,null,STOPPED} |
While we could tweak our logger configuration and set the log level to ERROR
for the framework and libraries logs, their INFO
can still be quite relevant when analyzing a test failure.
When scrolling through the log output of passing tests, we might also see stack traces and exceptions that are intended but might confuse newcomers as they wonder if something went wrong there.
Having a clean build log without much noise would better help us follow the current build. The bigger our test suite, the more we have to scroll.
If all tests pass, why pollute the console with log output from the tests? Our Maven build might also fail for different reasons than test failures, e.g., a failing OWASP dependency check or a dependency convergence issue. Getting fast to the root cause of the build failure is much simpler with a compact build log.
The Goal: Run Tests with Maven Silently
Our goal for this optimization is to have a compact Maven build log and only log the test output if it's really necessary (aka. tests are failing).
Gradle is doing this already by default. When running tests with Gradle, we'll only see a test summary after running our tests. There's no intermediate noise inside our console.
The goal is to achieve a somehow similar behavior as Gradle and run our tests silently. If they're passing, we're fine, and there's (usually) no need to investigate the log outcome of our tests. If one of our tests fails, report the build log to the console to analyze the test failure.
In short, with our target solution, we have two scenarios:
- No log output for tests in the console when all tests pass
- Print the log output of our tests when a test fails
The second scenario should be (hopefully) less likely. Hence most of our Maven builds should result in a compact and clean build log. We're fine with the log noise if there's a failure, as it helps us understand what went wrong.
Let's see how we can achieve this with the least amount of configuration.
The Solution: Customized Maven Setup
As a first step, we configure the desired log level for testing:
1 2 3 4 5 6 7 8 9 10 11 12 | <configuration> <include resource="/org/springframework/boot/logging/logback/base.xml"/> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <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> |
We're using Logback (any logger works) and log any INFO
(and above) statement to the console for the example above. We don't differentiate between our application's log and framework or test libraries.
Next comes the important configuration that'll make our test silent. The Maven Surefire (unit tests) and the Failsafe (integration tests) plugin allow redirecting the console output to a file. We won't see any test log output in the console with this configuration as it's stored within a file:
1 2 3 4 5 6 7 8 | <plugin> <artifactId>maven-surefire-plugin</artifactId> <version>3.0.0-M5</version> <configuration> <redirectTestOutputToFile>true</redirectTestOutputToFile> <reportsDirectory>${project.build.directory}/test-reports</reportsDirectory> </configuration> </plugin> |
When activating this functionality (redirectTestOutputToFile
), both plugins create an output file inside the target folder for each test class with the naming scheme TestClassName-output.txt
.
We can override the location of the output files using the reportsDirectory
configuration option. Overriding this location helps us store the output of the Surefire and Failsafe plugin at the same place:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | <plugin> <artifactId>maven-failsafe-plugin</artifactId> <version>3.0.0-M5</version> <executions> <execution> <goals> <goal>integration-test</goal> <goal>verify</goal> </goals> </execution> </executions> <configuration> <redirectTestOutputToFile>true</redirectTestOutputToFile> <reportsDirectory>${project.build.directory}/test-reports</reportsDirectory> </configuration> </plugin> |
This configuration for bot the Surefire and Failsafe plugin will mute our test runs, and Maven will only display a test execution summary for each test class:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 | [INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ spring-boot-example --- [INFO] [INFO] ------------------------------------------------------- [INFO] T E S T S [INFO] ------------------------------------------------------- [INFO] Running de.rieckpil.blog.assertj.AssertJTest [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.397 s - in de.rieckpil.blog.assertj.AssertJTest [INFO] Running de.rieckpil.blog.hamcrest.HamcrestTest [INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.149 s - in de.rieckpil.blog.hamcrest.HamcrestTest [INFO] Running de.rieckpil.blog.citrus.CitrusDemoTest [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.583 s - in de.rieckpil.blog.citrus.CitrusDemoTest [INFO] Running de.rieckpil.blog.xmlunit.XMLUnitTest [INFO] Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.189 s - in de.rieckpil.blog.xmlunit.XMLUnitTest [INFO] Running de.rieckpil.blog.MyFirstTest [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0 s - in de.rieckpil.blog.MyFirstTest [INFO] Running de.rieckpil.blog.jsonpath.JsonPayloadTest [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.034 s - in de.rieckpil.blog.jsonpath.JsonPayloadTest |
This compact build log makes it even fun to watch the test execution (assuming there are no flaky tests).
After running our tests, we can take a look at the content of the test-reports
folder:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 | target `-- test-reports |-- de.rieckpil.blog.MyFirstTest.txt |-- de.rieckpil.blog.assertj.AssertJTest.txt |-- de.rieckpil.blog.citrus.CitrusDemoTest-output.txt |-- de.rieckpil.blog.citrus.CitrusDemoTest.txt |-- de.rieckpil.blog.greenmail.MailServiceTest-output.txt |-- de.rieckpil.blog.greenmail.MailServiceTest.txt |-- de.rieckpil.blog.hamcrest.HamcrestTest.txt |-- de.rieckpil.blog.jsonassert.JSONAssertTest.txt |-- de.rieckpil.blog.jsonpath.JsonPayloadTest.txt |-- de.rieckpil.blog.junit5.ExtensionExampleTest-output.txt |-- de.rieckpil.blog.junit5.ExtensionExampleTest.txt |-- de.rieckpil.blog.junit5.JUnit5ExampleTest-output.txt |
For each test class, we'll find (at least) one text file that contains the test summary as we saw it in the build log. If the test prints output to the console, there'll be a -output.txt
file with the content:
de.rieckpil.blog.greenmail.MailServiceTest-output.txt
: All console output of the testde.rieckpil.blog.greenmail.MailServiceTest.txt
: The test summary, as seen in the build log
What's left is to extract the content of all our *-output.txt
files if our build is failing. As long as our tests are all green, we can ignore the content of the output files. In case of a test failure, we must become active and dump the file contents to the console.
For this purpose, we're using a combination of find
and tail
.For demonstration purposes, we'll use GitHub Actions. However, the present solution is portable to any other build server that provides functionality to detect a build failure and execute shell commands:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 | name: Maven Build on: [ push, pull_request ] jobs: build-project: runs-on: ubuntu-20.04 name: Build sample project steps: - name: Checkout code uses: actions/checkout@v2 - name: Set up JDK 11 uses: actions/setup-java@v2 with: java-version: 11.0 distribution: 'adopt' java-package: 'jdk' # ... more steps including running ./mvnw verify - name: Log test output on failure if: failure() || cancelled() run: find . -type f -path "*test-reports/*-output.txt" -exec tail -n +1 {} + |
As part of the last step of our build workflow, we find all *-output.txt
files and print their content. We only print the content of the test output files in case of a failure.
With GitHub Actions, we can conditionally execute a step using a boolean expression: if: failure() || cancelled()
. Both failure()
and cancelled()
are built-in functions of GitHub Actions. Every other CI server provides some similar functionality. We include cancelled()
to the expression to cover the scenario when our test suite is stuck and we manually stop (aka. cancel) the build.
If the build is passing, this last logging step is skipped, and no test log output is logged.
By using tail -n +1 {}
we print the file name before dumping its content to the console. This helps search for the failed test class to start the investigation:
1 2 3 | ==> ./target/test-reports/de.rieckpil.blog.greenmail.MailServiceTest-output.txt <== 06:35:17.474 [smtp:127.0.0.1:3025<-/127.0.0.1:64642] INFO c.i.greenmail.user.UserManager - Created user login [email protected] for address [email protected] with password [email protected] because it didn't exist before. 06:35:17.547 [smtp:127.0.0.1:3025<-/127.0.0.1:64644] INFO c.i.greenmail.user.UserManager - Created user login [email protected] for address [email protected] with password [email protected] because it didn't exist before. |
Summary: Silent and Compact Build Logs
We'll get compact Maven build logs with this small tweak to the Maven Surefire and Failsafe plugin and the additional step inside our build server. No more noisy test runs. We won't lose any test log output as we temporarily park it inside files and inspect the files if a test fails.
This configuration will only affect the way our tests are run with Maven. We can still see the console output when executing tests within our IDE.
We'll capture any test console output with this mechanism, both from logging libraries and plain System.out.println
calls.
This technique also works when running our tests in parallel. However, if we parallelize the test methods, the console statements may be out of order inside the test output file.
If you want to see this technique in action for a public repository, take a look at the Java Testing Toolbox repository on GitHub. As part of the main GitHub Actions workflow that builds the project(s) with Maven, you'll see the Java tests being run silently. If there's a build failure, you'll see the content of the test output files as one of the last jobs.
Joyful testing,
Philip