Is there any simple pattern of slf4j usage in unit tests?

Question

I'm using JUnit4 and Hibernate3 in my project. Hibernate depends on Slf4j and thus my project includes this library as well. Now I'd like to use Slf4j in unit tests in order to log supplementary testing information. Could you please provide a short example of how my unit test should look like in order to log just one line of text? Preferably without code duplication in multiple tests.

Answer 1

Why do you want to log things in your unit test? Unit tests should be pass/fail and should use the testing framework to indicate that. You don't want to be reading through output to see if the test passed or failed. And if it's failing, running it in your IDE/debugger is the best way to fix it.

Answer 2

It seems to be a bad smell to me.

You should always avoid manual inspection or verification for unit test.

Unit test should be automated, human intervention should only be needed if your build tools tell you that certain test failed, and the failure reason should be provided using all those verification methods (e.g. assertEquals)

Answer 3

We use log4j as our output logger;

private static Logger log = LoggerFactory.getLogger(MyClassHere.class);

slf4j should find and use log4j without issue if you configure it correctly. To make life easy, I would use this Eclipse pattern, since you will be writing this code a fair bit:

private static Logger log = LoggerFactory.getLogger(${enclosing_type}.class);
${:import(org.slf4j.Logger,org.slf4j.LoggerFactory)}

for tests I would recommend you don't rise above INFO level and keep most things to DEBUG. If you really want to trap lots of errors intelligently then I would recommend looking into PositronLogger which is a log file appender which will silently pick up on everything down to TRACE but only dump it to file if it captures ERROR; sort of like time travelling :)

http://github.com/andreaja/PositronLogger

Answer 4

I also like to use slf4j in my JUnit tests for my DAO class. It does help when you are creating a new test or modifying an old one. I usually leave my old logging output at debug level, and make my new logging statements at info level while I'm still actively working on the code in that method. One of my JUnit classes would look something like this:

package com.example.mydao;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
// other imports not shown...

public class TestMyDAO extends TestCase {

    private static final Logger logger = 
        LoggerFactory.getLogger(TestMyDAO.class);


    public void testA() {
        logger.debug("Logging from testA() method");
    }

    public void testB() {
        logger.debug("Logging from testB() method");
    }

    public void testThatIAmWorkingOn() {
        logger.info("Logging from my new test method at INFO level");
    }

}

I'm using log4j as the actual logging provider, so my log4j.xml configuration file looks like this:

<?xml version="1.0" encoding="UTF-8"?>
    <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
    <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">
    <appender name="consoleAppender" class="org.apache.log4j.ConsoleAppender">
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p  [%c{1}] %m %n" />
        </layout>
    </appender>

    <logger name="com.example.mydao" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="org.hibernate" additivity="false">
        <level value="WARN" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="org.hibernate.connection.DriverManagerConnectionProvider" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="org.hibernate.connection.C3P0ConnectionProvider" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="com.mchange" additivity="false">
        <level value="WARN" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="com.mchange.v2.resourcepool.BasicResourcePool" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <logger name="com.mchange.v2.c3p0.C3P0Registry" additivity="false">
        <level value="INFO" />
        <appender-ref ref="consoleAppender"/>
    </logger>

    <root>
        <priority value ="WARN" />
        <appender-ref ref="consoleAppender"/>
    </root>

</log4j:configuration>

This gives me the info-level output from my JUnit class, as well as some useful stuff from Hibernate runtime and other libraries used with Hibernate. Adjust to your own taste.

Finally, I need to make sure that all of the following libraries are in my classpath when I execute the JUnit tests:

• slf4j-api-1.6.0.jar
• slf4j-log4j12-1.6.0.jar
• log4j-1.2.16.jar
• log4j.xml (my configuration file, shown above)
• Some version of the JUnit runtime JAR
• All the JARs normally present when running your application in production

This is what I do when using log4j. If you use a different logging implementation, then adjust accordingly. It doesn't matter if you're using a different version of slf4j, as long as the "API" and implementation JARs are the same version (mine are both 1.6.0).