[FIXED] Maven Surefire Plugin not logging from org.junit.jupiter.api package

Issue

I'm getting some inconsistent behaviour in my unit test logging when either:

• Running tests via IntelliJ's Run interface
• Running tests via mvn test

I really want to see the following log statements when running mvn test, however they do not seem to be visible:

May 12, 2022 12:00:13 PM org.junit.jupiter.api.ClassOrderer$Random <clinit>
CONFIG: ClassOrderer.Random default seed: 155513463168987
May 12, 2022 12:00:13 PM org.junit.jupiter.engine.config.InstantiatingConfigurationParameterConverter logSuccessMessage
CONFIG: Using default class orderer 'org.junit.jupiter.api.ClassOrderer$Random' set via the 'junit.jupiter.testclass.order.default' configuration parameter.
May 12, 2022 12:00:13 PM org.junit.jupiter.api.MethodOrderer$Random <clinit>
CONFIG: MethodOrderer.Random default seed: 155513483010989

Inside my pom.xml:

<plugin>
    <groupId>org.apache.maven.plugins</groupId>
    <artifactId>maven-surefire-plugin</artifactId>
    <version>3.0.0-M5</version>
    <configuration>
        <systemPropertyVariables>
            <java.util.logging.config.file>
                ${project.build.testOutputDirectory}/logging.properties
            </java.util.logging.config.file>
        </systemPropertyVariables>
    </configuration>
</plugin>

Contents of src/test/resources/logging.properties:

.level=CONFIG
.handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=CONFIG

When running tests via IntelliJ's Run interface, I can see the following output, with the desired logs towards the bottom:

/Users/ian.jones/Library/Java/JavaVirtualMachines/openjdk-17.0.2/Contents/Home/bin/java -ea -Djava.util.logging.config.file=/Users/ian.jones/Development/my-app/target/test-classes/logging.properties -Didea.test.cyclic.buffer.size=1048576 -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=61653:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8 -classpath [omitted for brevity] com.intellij.rt.junit.JUnitStarter -ideVersion5 -junit5 com.myorg.OpenApiDocsGeneratorTest

May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.ServiceLoaderTestEngineRegistry loadTestEngines
CONFIG: Discovered TestEngines with IDs: [junit-jupiter (group ID: org.junit.jupiter, artifact ID: junit-jupiter-engine, version: 5.8.2, location: jar:file:/Users/ian.jones/.m2/repository/org/junit/jupiter/junit-jupiter-engine/5.8.2/junit-jupiter-engine-5.8.2.jar!/org/junit/jupiter/engine/JupiterTestEngine.class)]
May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
CONFIG: Loaded PostDiscoveryFilter instances: []
May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
CONFIG: Loaded LauncherDiscoveryListener instances: []
May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
CONFIG: Loaded TestExecutionListener instances: [org.junit.platform.launcher.listeners.UniqueIdTrackingListener@2781e022]
May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.LauncherConfigurationParameters loadClasspathResource
CONFIG: Loading JUnit Platform configuration parameters from classpath resource [file:/Users/ian.jones/Development/my-app/target/test-classes/junit-platform.properties].
May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
CONFIG: Loaded LauncherSessionListener instances: []
May 12, 2022 12:00:13 PM org.junit.platform.launcher.core.LauncherConfigurationParameters loadClasspathResource
CONFIG: Loading JUnit Platform configuration parameters from classpath resource [file:/Users/ian.jones/Development/my-app/target/test-classes/junit-platform.properties].
May 12, 2022 12:00:13 PM org.junit.jupiter.api.ClassOrderer$Random <clinit>
CONFIG: ClassOrderer.Random default seed: 155513463168987
May 12, 2022 12:00:13 PM org.junit.jupiter.engine.config.InstantiatingConfigurationParameterConverter logSuccessMessage
CONFIG: Using default class orderer 'org.junit.jupiter.api.ClassOrderer$Random' set via the 'junit.jupiter.testclass.order.default' configuration parameter.
May 12, 2022 12:00:13 PM org.junit.jupiter.api.MethodOrderer$Random <clinit>
CONFIG: MethodOrderer.Random default seed: 155513483010989
May 12, 2022 12:00:13 PM org.junit.jupiter.engine.config.InstantiatingConfigurationParameterConverter logSuccessMessage
CONFIG: Using default method orderer 'org.junit.jupiter.api.MethodOrderer$Random' set via the 'junit.jupiter.testmethod.order.default' configuration parameter.

However, when running mvn clean install, the logs which are important to me do not appear:

[INFO] --- maven-surefire-plugin:3.0.0-M5:test (default-test) @ my-app ---
[INFO] 
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[ERROR] May 12, 2022 12:10:06 PM org.junit.platform.launcher.core.ServiceLoaderTestEngineRegistry loadTestEngines
[ERROR] CONFIG: Discovered TestEngines with IDs: [junit-jupiter (group ID: org.junit.jupiter, artifact ID: junit-jupiter-engine, version: 5.8.2, location: jar:file:/Users/ian.jones/.m2/repository/org/junit/jupiter/junit-jupiter-engine/5.8.2/junit-jupiter-engine-5.8.2.jar!/org/junit/jupiter/engine/JupiterTestEngine.class)]
[ERROR] May 12, 2022 12:10:06 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
[ERROR] CONFIG: Loaded PostDiscoveryFilter instances: []
[ERROR] May 12, 2022 12:10:06 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
[ERROR] CONFIG: Loaded LauncherDiscoveryListener instances: []
[ERROR] May 12, 2022 12:10:06 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
[ERROR] CONFIG: Loaded TestExecutionListener instances: [org.junit.platform.launcher.listeners.UniqueIdTrackingListener@76c3e77a]
[ERROR] May 12, 2022 12:10:06 PM org.junit.platform.launcher.core.LauncherConfigurationParameters loadClasspathResource
[ERROR] CONFIG: Loading JUnit Platform configuration parameters from classpath resource [file:/Users/ian.jones/Development/my-app/target/test-classes/junit-platform.properties].
[ERROR] May 12, 2022 12:10:06 PM org.junit.platform.launcher.core.ServiceLoaderRegistry load
[ERROR] CONFIG: Loaded LauncherSessionListener instances: []
[INFO] Running ...

I have tried changing the version of maven-surefire-plugin to 3.0.0-M4 or 3.0.0-M6 but in both cases, this results in all the CONFIG logs disappearing from the output.

I have also tried explicitly setting the handlers for the classes in question, e.g.:

org.junit.jupiter.api.MethodOrderer$Random.handlers=java.util.logging.ConsoleHandler

But all this does is result in duplicate output log lines when running tests with Run, and doesn't change the output when running tests with mvn test.

Clearly it's partially working in that it is reading logging.config in both cases (if I remove this file, all CONFIG logs disappear when running mvn test) - but I have no idea why the behaviour is different, or how to fix that.

EDIT: Minimal pom.xml file

Here's a minimal pom.xml demonstrating the issue (I'm using Maven 3.8.5)

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>org.example</groupId>
    <artifactId>surefire-problem-demo</artifactId>
    <version>1.0-SNAPSHOT</version>

    <dependencies>
        <dependency>
            <groupId>org.junit.jupiter</groupId>
            <artifactId>junit-jupiter</artifactId>
            <version>5.8.2</version>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <properties>
        <maven.compiler.source>11</maven.compiler.source>
        <maven.compiler.target>11</maven.compiler.target>
    </properties>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-surefire-plugin</artifactId>
                <version>3.0.0-M7</version>
                <configuration>
                    <systemPropertyVariables>
                        <java.util.logging.config.file>
                            ${project.build.testOutputDirectory}/logging.properties
                        </java.util.logging.config.file>
                    </systemPropertyVariables>
                </configuration>
            </plugin>
        </plugins>
    </build>

</project>

Solution

Introduction

Let's consider the following versions as the current versions:

• Maven Surefire Plugin 3.0.0-M7.
• JUnit 5.8.2.

Root cause analysis

Analysis

Maven Surefire Plugin uses its JUnitPlatformProvider class. It may be observed in the output right before the «Tests» section:

<…>
[INFO] --- maven-surefire-plugin:3.0.0-M7:test (default-test) @ the-project ---
[INFO] Using auto detected provider org.apache.maven.surefire.junitplatform.JUnitPlatformProvider
[INFO] 
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
<…>

Please, see the implementation of the JUnitPlatformProvider.setupJunitLogger() method: maven-surefire/JUnitPlatformProvider.java at surefire-3.0.0-M7 · apache/maven-surefire:

private static void setupJunitLogger()
{
    Logger logger = Logger.getLogger( "org.junit" );
    if ( logger.getLevel() == null )
    {
        logger.setLevel( WARNING );
    }
}

Please, note the condition:

logger.getLevel() == null

Please, see the documentation of the Logger.getLevel() method:

public Level getLevel()

Get the log Level that has been specified for this Logger. The result may be null, which means that this logger's effective level will be inherited from its parent.

Returns:

this Logger's level

Please, note the statement:

The result may be null, which means that this logger's effective level will be inherited from its parent.

Analysis summary

This is (see the «Analysis» subsection) why:

1. A parent logger configuration is not taken into account by Maven Surefire Plugin.

   It does not seem to be a user-friendly behavior.
   Maybe, it is worth reporting it as a Maven Surefire Plugin issue.

2. It is necessary to introduce the explicit logger configuration for the org.junit package.

Solution

It is necessary to introduce the explicit logger configuration for the org.junit package:

org.junit.level=CONFIG

Follow-up: Checking provided complete pom.xml file

I have used the provided complete pom.xml file with the following preconditions.

I had used the same preconditions to test the solution.

Preconditions

Added test classes

Added 3 test classes annotated with @TestMethodOrder(MethodOrderer.Random.class) like this one:

import org.junit.jupiter.api.Assertions;
import org.junit.jupiter.api.MethodOrderer;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.TestMethodOrder;

@TestMethodOrder(MethodOrderer.Random.class)
public class Application1Test {
    @Test
    public void shouldAnswerWithTrue() {
        Assertions.assertTrue(true);
    }

    @Test
    public void shouldAnswerWithTrue2() {
        Assertions.assertTrue(true);
    }
}

Enabled parallel test execution

The content of the src/test/resources/junit-platform.properties file:

junit.jupiter.execution.parallel.enabled=true
junit.jupiter.execution.parallel.mode.default=concurrent

Added JUnit-related log level

The content of the src/test/resources/logging.properties:

.level=CONFIG
.handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=CONFIG
org.junit.level=CONFIG

Output

$ ./mvnw clean test 2>&1 | grep -F 'MethodOrderer.Random'
CONFIG: MethodOrderer.Random default seed: 7225497639767

Answered By - Sergey Vyacheslavovich Brunov
Answer Checked By - David Marino (JavaFixing Volunteer)