Best way of logging exceptions when tests fail (e.g. using a junit rule)
Asked Answered
B

3

6

When I'm running a complete test suite, it would be helpful if exceptions that caused a test to fail would appear in my (SLF4J-)log. What is the best method to achieve this?

What I would like

is a junit4 rule that handles exception logging for me. The code

@Rule
public TestRule logException = new TestWatcher() {
    @Override
    public void failed(Description d) {
        catch (Exception e) {
            logger.error("Test ({}) failed because of exception {}", d, e);
            throw e;
        }
    }
}

of course does not work, since I can only catch exceptions out of a try block. Is there a workaround to somehow achieve this in a similarly simple and general way?


BTW, what I'm doing right now

is logging the exception the moment it is created. But it would be nicer to log exceptions at the interface between caller and the library, so in my case in the test case. Not logging when the exceptions are created would also guarantee that they don't show up multiple times when the caller decides to log them.

Breather answered 21/9, 2011 at 16:28 Comment(2)
"it would be helpful if exceptions that caused a test to fail would appear in my log". Could you explain why? It seems an odd requirement. The test-runner reports ("logs" in the broadest sense) all test-cases that fail because of thrown exceptions.Preordain
I'd like to have one single log that contains everything. That way, I have everything in one place (can search and filter one file, no need to merge) and in chronological order.Breather
M
14

You need to extend TestRule, in particular the apply(). For an example, have a look at org.junit.rules.ExternalResource & org.junit.rules.TemporaryFolder.

ExternalResource looks like this:

public abstract class ExternalResource implements TestRule {
    public Statement apply(Statement base, Description description) {
        return statement(base);
    }

    private Statement statement(final Statement base) {
        return new Statement() {
            @Override
            public void evaluate() throws Throwable {
                before();
                try {
                    base.evaluate();
                } finally {
                    after();
                }
            }
        };
    }

    /**
     * Override to set up your specific external resource.
     * @throws if setup fails (which will disable {@code after}
     */
    protected void before() throws Throwable {
        // do nothing
    }

    /**
     * Override to tear down your specific external resource.
     */
    protected void after() {
        // do nothing
    }
}

TemporaryFolder then extends this and implements before() and after().

public class TemporaryFolder extends ExternalResource {
    private File folder;

    @Override
    protected void before() throws Throwable {
        // create the folder
    }

    @Override
    protected void after() {
        // delete the folder
    }

So the before gets called before the testMethod, and the after is called in the finally, but you can catch and log any Exception, like:

    private Statement statement(final Statement base) {
        return new Statement() {
            @Override
            public void evaluate() throws Throwable {
                before();
                try {
                    base.evaluate();
                } catch (Exception e) {
                    log.error("caught Exception", e);
                } finally {
                    after();
                }
            }
        };
    }

EDIT: The following works:

public class SoTest {
    public class ExceptionLoggingRule implements TestRule {
        public Statement apply(Statement base, Description description) {
            return statement(base);
        }

        private Statement statement(final Statement base) {
            return new Statement() {
                @Override
                public void evaluate() throws Throwable {
                    try {
                        base.evaluate();
                    } catch (Exception e) {
                        System.out.println("caught an exception");
                        e.printStackTrace(System.out);
                        throw e;
                    }
                }
            };
        }
    }

    @Rule public ExceptionLoggingRule exceptionLoggingRule = new ExceptionLoggingRule();
    @Rule public ExpectedException expectedException = ExpectedException.none();

    @Test
    public void testMe() throws Exception {
        expectedException.expect(IOException.class);
        throw new IOException("here we are");
    }
}

The test passes and you get the following output:

caught an exception
java.io.IOException: here we are
    at uk.co.farwell.junit.SoTest.testMe(SoTest.java:40)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
...

The order that the rules are applied is ExpectedException which calls ExceptionLoggingRule which calls the testMe method. The ExceptionLoggingRule catches the Exception, logs it and rethrows it, and it is then processed by ExpectedException.

If you want to log only unexpected exceptions, you just switch the declaration order of the rules:

    @Rule public ExpectedException expectedException = ExpectedException.none();
    @Rule public ExceptionLoggingRule exceptionLoggingRule = new ExceptionLoggingRule();

That way, expectedException is applied first (i.e. nested in exceptionLoggingRule), and only rethrows exceptions that are not expected. Furthermore, if some exception was expected and none occured, expectedException will throw an AssertionError which will also get logged.

This evaluation order isn't guaranteed, but it is quite unlikely to vary unless you're playing with very different JVMs, or inheriting between Test classes.

If the evaluation order is important, then you can always pass one rule to the other for evaluation.

EDIT: With the recently released Junit 4.10, you can use @RuleChain to chain rules correctly:

public static class UseRuleChain {
   @Rule
   public TestRule chain= RuleChain
                          .outerRule(new LoggingRule("outer rule")
                          .around(new LoggingRule("middle rule")
                          .around(new LoggingRule("inner rule");

   @Test
   public void example() {
           assertTrue(true);
   }
}

writes the log

starting outer rule
starting middle rule
starting inner rule
finished inner rule
finished middle rule
finished outer rule
Madelynmademoiselle answered 21/9, 2011 at 17:30 Comment(6)
Hm, come to think of it: will this be compatible with the ExpectedException rule and with @Test(expected=ExceptionName.class)? In which order are the rules/Statements.evaluate() called? If this ExceptionLoggingRule were called within ExpectedException rule, I could rethrow the exception for ExceptionLoggingRule. So all exceptions would be logged :( but it would work. It would be even better if there was way to access the exception after the junit-framework has evaluated whether the test has passed or failed (as I tried in my code example). Do you know of such a way?Breather
Added example implementation.Madelynmademoiselle
Thanks a lot :) Can you give a reference where/how the evaluation order is decided? (#2730865 says that the first declared rule will not be executed before the second declared rule).Breather
In fact there isn't a reference, but there will be when I get around to raising an issue. We should change the description in the javadoc for @Rule. Like I said, ExpectedException calls ExceptionLoggingRule (through calling base.evaluate()) which calls testMe(). So ExpectedException gets the chance to execute first.Madelynmademoiselle
@RuleChain now allows you to chain rules correctly in JUnit 4.10Madelynmademoiselle
For more power you could also implement something in this package: commons.apache.org/lang/api-2.6/org/apache/commons/lang/…Wortham
A
2

Look outside the box... What are you using to run the tests? Most environments for running tests (e.g., Ant, Jenkins, Maven, etc.) have means for using a testrunner that outputs an XML file, with support for aggregating the XML files from a suite into a comprehensive report.

Anorthic answered 21/9, 2011 at 17:30 Comment(1)
I'm running my test suites either within Eclipe (and Infinitest) or in Ant. Since I often look into my log file that is accumulated over the complete test suite, I really need the exceptions to be reported in there.Breather
C
0

This seems so easy that I think I am wrong and you are asking something different, but maybe I can help:

JUnit 4.X

@Test(expected=Exception.class)

is going to pass the test if the exception is thrown in the test, or fail with a message captured by the Junit framework

Causality answered 5/10, 2011 at 21:53 Comment(1)
Using the parameter expected is good for testing exceptions. What I want is a general solution for logging unexpected exceptions. Take a look at JUnit 4.X rules; they offer these general behaviors over all test methods. Matthew shows in his reply how you can implement a rule for exception logging and how to compatibly chain it with other rules.Breather

© 2022 - 2024 — McMap. All rights reserved.