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.

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

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

Solution 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

Solution 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

View more solutions

Comments

[BjornS]

Because sometimes its useful to know WHY a test failed, or perhaps to print performance metrics in case you want to casually keep an eye on these.

[dty]

If you want to do performance testing, do it properly and capture and graph the numbers. Casually eyeballing some numbers from a UT run is NOT the way to measure performance. And as to why a test failed, you should write your assertions so the text tells you what went wrong. At work, our product has tens of thousands of unit tests; where do you think we'd be if we had to read output from those?

[BjornS]

I didn't say performance testing, I simply said to casually keep track of it as an example of why you might want logging in your tests. As for your work, yes we have tens of thousands of tests as well and you'd be surprised how quickly you can find the information you want related to a specific test. Besides, you won't need to read them unless you really need to, and when you really need to, its damn handy to already have the logs there.

[dty]

I'm sorry, I just don't get it. You are either interested in performance or not. If you are, spotting some numbers in the middle of a log file is not the way to keep track of what's going on. As for other "valuable" logging, the system under test is presumably doing its own logging too, so seeing the logging done by the test among any other logging must be tricky. I come back to what I originally said - unit tests should be red/green, pass/fail. And if a test fails, the failure message should tell you why.

[yegor256]

@dty Logging during testing is important WHILE you're creating the test. Once the test is done, the log messages are obsolete, but they don't harm anyone. You will be interested to get back to them when the test fails again, say, in 1 year. Of course, in an ideal world only assertions would be enough. But we need logging very very often.

[yegor256]

I need to do this getLogger() in every unit test inside some @Before-annotated method, right?

[dty]

In all my (considerable!) years, I've never felt the need to add logging to a unit test. To me, this smells of the unit test being too complex. But anyway, I'm not sure how your question is different from "how do I use slf4j". I'm not sure how using it from within a unit test is relevant to the question. What's different about using it from a unit test vs using it from production code?

[yegor256]

@dty I don't know, that's why I'm asking :) Btw I up-voted your answer since I consider it relevant to my question and it will definitely affect my future attitude to "logging in testing". Thank you.

[dty]

Hehehe! Good. Making people think and challenge assumptions is just part of the service. :-)

[BjornS]

No, just the private static reference, then you can simply call log.debug("some stuff"); wherever you like. Edit: I should clarify; the LoggerFactory.getLogger() is part of the static reference, you do not need to call it in your @Before, simply enter it as a field in your test class and it should work. A brief example: class MyTests { private static Logger log = LoggerFactory.getLogger(MyTests.class); @Test public void magic() { log.info("..."); } }

[David Harkness]

And to avoid code duplication you could move the imports and Logger declaration to an abstract TestCase subclass.

[dty]

Wow! Nearly 4 years late to the party. Welcome on board. :-/

[jacobq]

Sure it does. The OP wanted to know what the code should look like to do this, and many of us are recommending that that code not exist. That is how it should be.

[Adrian Shum]

interesting enough, another answer from dyt is essentially saying similar thing (people should avoid logging in unit tests because of blablabla). My answer is receiving more downvotes. LOL

[Ricardo Stuven]

SimpleLogger default log level is INFO. To change it to DEBUG, for instance, use the JVM option -Dorg.slf4j.simpleLogger.defaultLogLevel=DEBUG

[AntonPiatek]

Logging during tests is often incredibly invaluable, especially when the tests fail. This of course needs to be balanced against too much logging when the tests are passing or the logs become unreadable.

[Adrian Shum]

@AntonPiatek That's actually wrong. When a test fail, those pre-defined log message rarely helps in identifying the problem. Over 99% of time, you need to look into the test, doing some debugging (which may include printing out debug messages IN THE DEBUG PROCESS). However you shouldn't keep those log message in the test after your debug and test fixing work. If you can think of some case that may fail and need log message inspection, write proper assertion instead.