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.

@Test
public void tc_shallPass() {
	System.out.println("stuff printed during execution");
	assertTrue(true);
}

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

public class TestClass {
	@Rule
	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 {
        @Override
        protected void before() throws Throwable {
            timeStart = System.currentTimeMillis();
            out.write(beforeContent.getBytes());
        };


        @Override
        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);
    }
}