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);
    }
}
Advertisements

Test suite pollution – missing term in test glossary

Test suite pollution is when one or more automated test cases deliberately are allowed to fail in a test suite. This usually leads to the executing test suite to be un-attended since errors are expected, a very unfortunate situation during development. New defects surfacing can easily be missed out and the longer the test suite gets ignored recovering it to stable can be cumbersome.

This is just an attemp to clarifying one of the ‘buzz’ terms I preach to my team. Please correct me if you think I am out of line.