Logging and expected Exceptions during testing

Question

In my app code it is common that where something goes wrong during app use I want as much information as possible about the circumstances to be logged, including if applicable the stack trace of an Exception which has been thrown.

But during testing I don't want these stack traces to be logged, cluttering up the log file to no purpose.

If this is a situation where the test itself creates an Exception object you can potentially give it a message which can identify it as a dummy Exception, like so:

given:
    indexMgr.queryParser = Mock( QueryParser ){
        parse(_) >> { throw new Exception( 'dummy parse problem' )}
    }

and then in the app code do this:

try {
    query = queryParser.parse(queryString)
}catch( e ) {
    log.debug( "QP exception msg: $e.message" )

    // we don't want a stack trace to be logged if this is a dummy Exception deliberately thrown during testing
    if( ! e.message.contains( 'dummy' )) {
        // this will log the stack trace of e
        log.error( 'query threw Exception in QP.parse()', e )
    }
    return false
}

... but there are 2 problems with this: firstly it is not always the case that an expected Exception will be created by the testing code, rather than by the app code, and secondly that it feels wrong to be checking for conditions identifying the conduct of a test in the actual app code.

Is there a "best practice" way of tackling this?

Answer 1

If just dropping a stack trace from a line is fine, you can configure the exception conversion logic in a logger's pattern layout. Below is an example using log4j2:

public class ExceptionOutput {
    private static final Logger LOG = LoggerFactory.getLogger(ExceptionOutput.class);

    public static void main(String[] args) {
        LOG.info("Foo", new NullPointerException("MESSAGE"));
    }
}

log4j2 configuration:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"
                           alwaysWriteExceptions="false"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Take note of alwaysWriteExceptions=false. It disables exceptions output completely. Now if we run the code we will get:

01:04:50.151 [main] INFO  ExceptionOutput - Foo

But if you revert to alwaysWriteExceptions=true, which is also the default behaviour if the parameter is omitted, then you get:

01:07:03.018 [main] INFO  ExceptionOutput - Foo
java.lang.NullPointerException: MESSAGE
    at ExceptionOutput.main(ExceptionOutput.java:8)

But there is more to this. For more flexibility you can use %throwable{...} conversion word in the pattern as explained here in the Patterns table for the respective conversion pattern. In order to apply the logic only to tests you can have log4j2-test.xml on your classpath as explained here. Similar functionality of exceptions conversion also exists for other logging libraries, e.g. logback