ant and junit 5 – outputting test duration and failure to the log

In JUnit 5, you use the junitlauncher Ant task rather than the junit Ant task. Unfortunately, this isn’t a drop in replacement. In addition to needing a workaround to set system properties, you also need a workaround to write the test results to the console log.

JUnit 4

With JUnit 4 and Ant, you got output that looked list this for each test run. In the console. Real time while the build was running. This was really useful.

[junit] Running com.javaranch.jforum.MissingHeadTagTest
[junit] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.685 sec

The problem

JUnit 5 itself provides a number of built in options for this. However, Ant integration renders this “not very useful” for a few reasons.

    1. I want to use the legacy listeners. For example:
      <listener type="legacy-xml" sendSysOut="true" sendSysErr="true" />
      <listener type="legacy-plain"sendSysOut="true"sendSysErr="true"/>
      
      

      However, if I enabled sendSysOut and sendSysErr to them, all the listeners present redirect away from System.out. This means if I try to use the built it LoggingListener, it also redirects to the file and I don’t see it in the console. This means, I have to chose between the legacy listeners and seeing real time data.

    2. Ant seems to pass a fileset as individual tests. This means that running this code, prints a summary for each test rather than the whole thing at the end.
      <junitlauncher haltOnFailure="true" printsummary="true">
           <classpath refid="test.classpath" />
           <testclasses outputdir="build/test-report">
      	<fileset dir="build/test">
      	  <include name="**/*Tests.class" />
              </fileset>
      </junitlauncher>
      

      It looks like this. The summary tells me about each run, but not with the test names so not useful anyway.

      [junitlauncher] Test run finished after 117 ms
      [junitlauncher] [         3 containers found      ]
      [junitlauncher] [         0 containers skipped    ]
      [junitlauncher] [         3 containers started    ]
      [junitlauncher] [         0 containers aborted    ]
      [junitlauncher] [         3 containers successful ]
      [junitlauncher] [         0 containers failed     ]
      [junitlauncher] [        15 tests found           ]
      [junitlauncher] [         0 tests skipped         ]
      [junitlauncher] [        15 tests started         ]
      [junitlauncher] [         0 tests aborted         ]
      [junitlauncher] [        15 tests successful      ]
      [junitlauncher] [         0 tests failed          ]
      [junitlauncher] Test run finished after 14 ms
      [junitlauncher] [         2 containers found      ]
      [junitlauncher] [         0 containers skipped    ]
      [junitlauncher] [         2 containers started    ]
      [junitlauncher] [         0 containers aborted    ]
      [junitlauncher] [         2 containers successful ]
      [junitlauncher] [         0 containers failed     ]
      [junitlauncher] [        10 tests found           ]
      [junitlauncher] [         0 tests skipped         ]
      [junitlauncher] [        10 tests started         ]
      [junitlauncher] [         0 tests aborted         ]
      [junitlauncher] [        10 tests successful      ]
      [junitlauncher] [         0 tests failed          ]
    3. If I use JUnit Launcher’s fail on error property, it fails on the first test rather than telling me about all of them. (I don’t use this feature anyway.)
    4. Custom extensions also have their system out/err redirected to the legacy listeners.

The solution

This feels like a hacky workaround. But I only have one project that uses Ant so I don’t have to worry about duplicate code. The legacy listeners are useful so I don’t want to get rid of them.

I wrote a custom listener that stores the results in memory for each test and writes it to disk after each test class runs. That way it gets all the data, not just the last one. And then Ant writes it out.

<target name="test.junit.launcher" depends="compile">
		<junitlauncher haltOnFailure="false" printsummary="false">
			<classpath refid="test.classpath" />
			<testclasses outputdir="build/test-report">
				<fileset dir="build/test">
					<include name="**/*Tests.class" />
				</fileset>
				<listener type="legacy-xml" sendSysOut="true" sendSysErr="true" />
				<listener type="legacy-plain" sendSysOut="true" sendSysErr="true" />
				<listener classname="com.example.project.CodeRanchListener" />
			</testclasses>
		</junitlauncher>
		<loadfile property="summary" srcFile="build/status-as-tests-run.txt" />
		        <echo>${summary}</echo>
	</target>

And the listener

package com.example.project;

import java.io.*;
import java.time.*;

import org.junit.platform.engine.*;
import org.junit.platform.engine.TestDescriptor.*;
import org.junit.platform.engine.TestExecutionResult.*;
import org.junit.platform.launcher.*;

public class MyListener implements TestExecutionListener {
	
	private StringWriter inMemoryWriter = new StringWriter();

	private int numSkippedInCurrentClass;
	private int numAbortedInCurrentClass;
	private int numSucceededInCurrentClass;
	private int numFailedInCurrentClass;
	private Instant startCurrentClass;

	private void resetCountsForNewClass() {
		numSkippedInCurrentClass = 0;
		numAbortedInCurrentClass = 0;
		numSucceededInCurrentClass = 0;
		numFailedInCurrentClass = 0;
		startCurrentClass = Instant.now();
	}

	@Override
	public void executionStarted(TestIdentifier testIdentifier) {
		if ("[engine:junit-jupiter]".equals(testIdentifier.getParentId().orElse(""))) {
			println("Ran " + testIdentifier.getLegacyReportingName());
			resetCountsForNewClass();
		}
	}

	@Override
	public void executionSkipped(TestIdentifier testIdentifier, String reason) {
		numSkippedInCurrentClass++;
	}

	@Override
	public void executionFinished(TestIdentifier testIdentifier, TestExecutionResult testExecutionResult) {
		if ("[engine:junit-jupiter]".equals(testIdentifier.getParentId().orElse(""))) {
			int totalTestsInClass = numSucceededInCurrentClass + numAbortedInCurrentClass
					+ numFailedInCurrentClass + numSkippedInCurrentClass;
			Duration duration = Duration.between(startCurrentClass, Instant.now());
			double numSeconds = duration.getNano() / (double) 1_000_000_000;
			String output = String.format("Tests run: %d, Failures: %d, Aborted: %d, Skipped: %d, Time elapsed: %f sec",
					totalTestsInClass, numFailedInCurrentClass, numAbortedInCurrentClass,
					numSkippedInCurrentClass, numSeconds);
			println(output);

		}
		// don't count containers since looking for legacy JUnit 4 counting style
		if (testIdentifier.getType() == Type.TEST) {
			if (testExecutionResult.getStatus() == Status.SUCCESSFUL) {
				numSucceededInCurrentClass++;
			} else if (testExecutionResult.getStatus() == Status.ABORTED) {
				println("  ABORTED: " + testIdentifier.getDisplayName());
				numAbortedInCurrentClass++;
			} else if (testExecutionResult.getStatus() == Status.FAILED) {
				println("  FAILED: " + testIdentifier.getDisplayName());
				numFailedInCurrentClass++;
			}
		}
	}
	
	private void println(String str) {
		inMemoryWriter.write(str + "\n");
	}
	
	/*
	 * Append to file on disk since listener can't write to System.out (becuase legacy listeners enabled)
	 */
	private void flushToDisk() {
		try (FileWriter writer = new FileWriter("build/status-as-tests-run.txt", true)) {
			writer.write(inMemoryWriter.toString());
		} catch (IOException e) {
			throw new UncheckedIOException(e);
		}
	}

	@Override
	public void testPlanExecutionFinished(TestPlan testPlan) {
		flushToDisk();
	}
}

 

JUnit 5 – assertAll

I gave a half day JUnit 5 workshop at DevNexus last week. When I covered assertAll(), an interesting piece of code came up. In JUnit 5, there is an assertAll() which runs all of the assertions it contains so you can see all of them that failed at once.  This replaces the need for AssertJ’s SoftAssertions.

So how many assertions do you think this will fail with?

@Test
public void all() {
  assertAll("message", () -> {
    assertEquals(1, 2);
    assertEquals(3, 4);
  });
}

The fact that this is a blog post should get you nice and suspicious. The answer is one:

org.opentest4j.MultipleFailuresError: message (1 failure)
expected: <1> but was: <2>

Why is this? Well, remember that assertAll takes a vararg of Executables (lambdas in this case.) However, the above code only has one lambda. So JUnit runs the two asserts in the same block which makes them happen sequentailly.

To fix this, you need to pass separate lambdas for each assertions.

@Test
public void all() {
  assertAll("message", 
	() -> assertEquals(1, 2), 
	() -> assertEquals(3, 4));
  }
}

Ah this one tells you about both failures.

org.opentest4j.MultipleFailuresError: message (2 failures)
expected: <1> but was: <2>
expected: <3> but was: <4>

Thanks to Steve Kiley for asking the question that led to this blog post!

junit 5, gradle and containers

Up until recently, I’ve been using JUnit 5 with Eclipse and Maven. As I started using it with Gradle, I became frustrated that you couldn’t see the number of tests run when the tests succeeded. (Don’t worry; this is an easily solvable problem.)

First JUnit 4

You can add code to have Groovy print the number of tests. This matches the number of tests that Eclipse/Maven say are run.

test {
   afterSuite { desc, result ->
    	     if (!desc.parent)
        		println("${result.resultType} " +
            "(${result.testCount} tests, " +
            "${result.successfulTestCount} successes, " +
            "${result.failedTestCount} failures, " +
            "${result.skippedTestCount} skipped)")
   }
}

On to JUnit 5
It’s even less code to ask JUnit 5 to print the test results:

junitPlatform {
  details 'tree'
}

This prints something like

Test run finished after 2518 ms
 [ 20 containers found ]
 [ 0 containers skipped ]
 [ 20 containers started ]
 [ 0 containers aborted ]
 [ 20 containers successful ]
 [ 0 containers failed ]
 [ 27 tests found ]
 [ 1 tests skipped ]
 [ 26 tests started ]
 [ 0 tests aborted ]
 [ 26 tests successful ]
 [ 0 tests failed ]

I agree that I have 27 tests with 1 skipped. But what’s this 20 containers? As you can see from the tree, we have:

  • 1 – JUnit Vintage – to run the JUnit 3/4 tests
  • 1 – JUnit Jupiter – to run the JUnit 5 tests (I didn’t have any in the project at the time I captured this tree so it is an empty container; but still counts)
  • 9 – JUnit test classes
  • 9 – The nine data elements in my parameterized test.

├─ JUnit Vintage ✔
│ ├─ com.devnexus.workshop.junit5.CentennialOlympicParkTest ✔
│ │ ├─ oldestForFirstElement ✔
│ │ ├─ oldestForLastElement ✔
│ │ ├─ oldestForEmptyList ✔
│ │ └─ url ✔
│ ├─ com.devnexus.workshop.junit5.EarthquakeTimeoutTest ✔
│ │ └─ timeout ✔
│ ├─ com.devnexus.workshop.junit5.ParkBuildingTest ✔
│ │ ├─ equalsValues ✔
│ │ └─ hashCodeValues ✔
│ ├─ com.devnexus.workshop.junit5.EarthquakeTest ✔
│ │ ├─ usingStandalone ✔
│ │ ├─ noMessageChecking ✔
│ │ └─ usingRule ✔
│ ├─ com.devnexus.workshop.junit5.GeorgiaAquariumTest ✔
│ │ ├─ namesOfShows ✔
│ │ └─ numberLines ✔
│ ├─ com.devnexus.workshop.junit5.OlympicsDatesTest ✔
│ │ ├─ [1996-07-19] ✔
│ │ │ └─ date[1996-07-19] ✔
│ │ ├─ [1996-07-20] ✔
│ │ │ └─ date[1996-07-20] ✔
│ │ ├─ [1996-07-31] ✔
│ │ │ └─ date[1996-07-31] ✔
│ │ ├─ [1996-08-03] ✔
│ │ │ └─ date[1996-08-03] ✔
│ │ ├─ [1996-08-04] ✔
│ │ │ └─ date[1996-08-04] ✔
│ │ ├─ [1996-07-18] ✔
│ │ │ └─ date[1996-07-18] ✔
│ │ ├─ [1996-08-05] ✔
│ │ │ └─ date[1996-08-05] ✔
│ │ ├─ [1997-07-18] ✔
│ │ │ └─ date[1997-07-18] ✔
│ │ └─ [1995-08-01] ✔
│ │ └─ date[1995-08-01] ✔
│ ├─ com.devnexus.workshop.junit5.CentennialOlympicParkEnumTest ✔
│ │ └─ allClosingTimesAfter9pm ✔
│ ├─ com.devnexus.workshop.junit5.ShakeExceptionTest ✔
│ │ └─ message ↷ this test is ignored becuase it is unnecessary
│ └─ com.devnexus.workshop.junit5.GeorgiaAquariumWaitTest ✔
│ ├─ plentyOfTime ✔
│ ├─ exactOpening ✔
│ ├─ anyMinuteNow ✔
│ └─ alreadyOpen ✔
└─ JUnit Jupiter ✔

Test run finished after 2518 ms
[ 20 containers found ]
[ 0 containers skipped ]
[ 20 containers started ]
[ 0 containers aborted ]
[ 20 containers successful ]
[ 0 containers failed ]
[ 27 tests found ]
[ 1 tests skipped ]
[ 26 tests started ]
[ 0 tests aborted ]
[ 26 tests successful ]
[ 0 tests failed ]