JUnit @Rule for printing test case start and end information

If you are watching the test execution trace during run-time and is missing the information about when a test cases starts and ends, then it can be easily fixed by adding a JUnit rule that prints out this information.

[TEST START] tc_shallPass
stuff printed during execution
[TEST ENDED] Time elapsed: 1.835 sec

The start and end tags gets generated automatically and hence no need to add any test case specific printing.

public void tc_shallPass() {
	System.out.println("stuff printed during execution");

To hook up the rule to all test cases in a class it has to be declared and instantiated first.

public class TestClass {
	public TestCasePrinterRule pr = new TestCasePrinterRule(System.out);
	// @Test
	// ...

So far so good, but how is this claimed to be “easily fixed” rule implemented then? Pretty straight forward by implmenting the org.junit.rules.TestRule and using a private class extending the org.junit.rules.ExternalResource. The example below calculates the execution time for the test case as well as providing the name of the current test case.

During run-time the start message will be printed before any other @Before annotated methods in the class but after the @BeforeClass methods. The apply method handles the creation of start and end tags since it has access to the test case description content, org.junit.runner.Description. The actual printing is done in the overridden before and after methods.

package com.yourcompany.customrules;

import java.io.IOException;
import java.io.OutputStream;
import java.text.DecimalFormat;

import org.junit.rules.ExternalResource;
import org.junit.rules.TestRule;
import org.junit.runner.Description;
import org.junit.runners.model.Statement;

public class TestCasePrinterRule implements TestRule {

    private OutputStream out = null;
    private final TestCasePrinter printer = new TestCasePrinter();

    private String beforeContent = null;
    private String afterContent = null;
    private long timeStart;
    private long timeEnd;
    public TestCasePrinterRule(OutputStream os) {
        out = os;

    private class TestCasePrinter extends ExternalResource {
        protected void before() throws Throwable {
            timeStart = System.currentTimeMillis();

        protected void after() {
            try {
                timeEnd = System.currentTimeMillis();
                double seconds = (timeEnd-timeStart)/1000.0;
                out.write((afterContent+"Time elapsed: "+new DecimalFormat("0.000").format(seconds)+" sec\n").getBytes());
            } catch (IOException ioe) { /* ignore */

    public final Statement apply(Statement statement, Description description) {
        beforeContent = "\n[TEST START] "+description.getMethodName()+"\n"; // description.getClassName() to get class name
        afterContent =  "[TEST ENDED] ";
        return printer.apply(statement, description);

2 Responses to “JUnit @Rule for printing test case start and end information”

  1. Marcelo Daniel Sales Says:

    Amazing man! very useful. Thanks for sharing.

  2. Tom Bombadil Says:

    Helped me with debugging, thanks! I was just wondering, what the correct Logger would be, to be printed at the same place as the Unittests from maven.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: