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

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).

Answer 2

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 3

Another solution is to switch the logging implementation to a simple implementation just for tests.

So in your pom.xml

    <!-- Depend on slf4j API -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>1.7.12</version>
    </dependency>

    <!-- Use SimpleLogger as the slf4j implementation in test -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-simple</artifactId>
        <version>1.7.12</version>
        <scope>test</scope>
    </dependency>

    <!-- Use log4j as the slf4j implementation during runtime (not test) -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>1.7.12</version>
        <scope>runtime</scope>
    </dependency>

The SimpleLogger just logs everything to stderr by default and doesn't require any configuration files

Answer 4

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 5

Adding logging while writing new tests is useful. At the same time, when the tests are being run in a CI or CD pipeline, you want logging to be disabled (or at least less verbose). Sometimes the failures are transient especially in an end-to-end run, so having relevant output on the console log of CI jobs are helpful. This article describes it very well - https://gualtierotesta.wordpress.com/2015/11/01/tutorial-logging-during-tests/

Answer 6

If using log4j 1 as the underlying slf4j implementation

log4j doesn't log anything by default unless you,

• have a log4j.properties file on the classpath
• set -Dlog4j.configuration=file:///path/to/log4j.properties. If using maven this can be done in your maven-surefire-plugin configuration.

• setup the log4j configuration programmatically, say in a @BeforeClass method

  @BeforeClass
  public static void beforeClass() {
      BasicConfigurator.resetConfiguration();
      BasicConfigurator.configure();
  }
  

  This just works, however it needs to be put on every unit test which is a pain. So I don't recommend except if you temporarily need it to quickly get something to work.

Answer 7

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)