On my current project, we’re using the logback framework (behind SL4J) to do logging. For some parts of our system, it was particularly important some information made their way into the log files, and so we wanted to not test the correct output. Rather than do it with interaction based tests, I followed the pattern that I described in a previous post.

Here’s a test I might write (note that I’m writing the test in a way to actually test the appender behaviour in this case because my domain class doesn’t nothing special):

package com.thekua.spikes;

import org.junit.After;
import org.junit.Test;
import static org.hamcrest.Matchers.is;
import static org.junit.Assert.assertThat;

public class LogbackCapturingAppenderTest {
    @After
    public void cleanUp() {
        LogbackCapturingAppender.Factory.cleanUp();
    }

    @Test
    public void shouldCaptureAGivenLog() throws Exception {
        // Given
        LogbackCapturingAppender capturing = LogbackCapturingAppender.Factory.weaveInto(OurDomainWithLogger.LOG);
        OurDomainWithLogger domainClass = new OurDomainWithLogger();

        // when
        domainClass.logThis("This should be logged");

        // then
        assertThat(capturing.getCapturedLogMessage(), is("This should be logged"));
    }

    @Test
    public void shouldNotCaptureAGiveLogAfterCleanUp() throws Exception {
        // Given
        LogbackCapturingAppender capturing = LogbackCapturingAppender.Factory.weaveInto(OurDomainWithLogger.LOG);
        OurDomainWithLogger domainClass = new OurDomainWithLogger();
        domainClass.logThis("This should be logged at info");
        LogbackCapturingAppender.Factory.cleanUp();

        // when
        domainClass.logThis("This should not be logged");

        // then
        assertThat(capturing.getCapturedLogMessage(), is("This should be logged at info"));
    }
}

And the corresponding Logback appender used in tests.

package com.thekua.spikes;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.Appender;
import ch.qos.logback.core.AppenderBase;

import java.util.ArrayList;
import java.util.List;

public class LogbackCapturingAppender extends AppenderBase<ILoggingEvent> {
    public static class Factory {
        private static List<LogbackCapturingAppender> ALL = new ArrayList<LogbackCapturingAppender>();

        public static LogbackCapturingAppender weaveInto(org.slf4j.Logger sl4jLogger) {
            LogbackCapturingAppender appender = new LogbackCapturingAppender(sl4jLogger);
            ALL.add(appender);
            return appender;
        }

        public static void cleanUp() {
            for (LogbackCapturingAppender appender : ALL) {
                appender.cleanUp();
            }
        }
    }

    private final Logger logger;
    private ILoggingEvent captured;

    public LogbackCapturingAppender(org.slf4j.Logger sl4jLogger) {
        this.logger = (Logger) sl4jLogger;
        connect(logger);
        detachDefaultConsoleAppender();
    }

    private void detachDefaultConsoleAppender() {
        Logger rootLogger = getRootLogger();
        Appender<ILoggingEvent> consoleAppender = rootLogger.getAppender("console");
        rootLogger.detachAppender(consoleAppender);
    }

    private Logger getRootLogger() {
        return logger.getLoggerContext().getLogger("ROOT");
    }

    private void connect(Logger logger) {
        logger.setLevel(Level.ALL);
        logger.addAppender(this);
        this.start();
    }

    public String getCapturedLogMessage() {
        return captured.getMessage();
    }

    @Override
    protected void append(ILoggingEvent iLoggingEvent) {
        captured = iLoggingEvent;
    }

    private void cleanUp() {
        logger.detachAppender(this);

    }
}

I thought it’d be useful to share this and I’ve created a github project to host the code.

I’ve seen a number of different patterns for testing logging and we just ran into this again at work, so I thought it’d be worth writing up a couple of them.

Simple logging
Many of the java based logging frameworks allow you to log and then choose to separate what you log from what needs to be done by attaching appenders to them. The common pattern here is to declare a static log instance inside each class, typically using the fully qualified class name. Most logging frameworks then treat this as a hierarchy of loggers that allow you to configure what type of logging at different levels.

I find the best strategy for testing this style of logging is to add an in memory appender that will capture the output that is sent to the logging framework. I will post an example with given frameworks in a second, but here are a few different concerns you need to think about:

• Getting a reference to the log – Most loggers are made private static. You can choose to break encapsulation slightly by weakening the access to package local just so that a test can get access to the log. I find that injecting it in as a dependency in the constructor appears to complicated, and dislike setter based dependency injection in an attempt to keep fields more immutable.
• Creating an appender to capture the output – This is where you’ll have to go to whichever logging framework and find out how appenders work. Most have a console appender, or something that you can simply extend and capture a logging event
• Make the appender capture the output – This is pretty easy. You must make a choice whether or not you want only your appender to capture the log events, or if you want it to go to other appenders as well.
• Clean up – The consequence of adding an appender with state is not a problem in a single test. When wired up across a long test suite, you potentially increase the amount of memory being consumed to the point where you’ll get out of memory errors. I find that it’s important to make sure that your appenders remove themselves from the logger at the end of the test to avoid side effects and to make sure they get garbage collected by the JVM. In a following post, you’ll see the pattern I tend to use.

More complex logging services
If you’re application requires more than just file based logging, and other actions need to be performed, you may still consider injecting a type of logger into the class that uses it. At this point, testing it becomes like any other interaction-based test and you can probably use mocking or stubbing to test the correct things are passed to to it.

By default, I wouldn’t really go through the motions of setting up a logging service unless there was some real need for it. The standard style of loggers and configuration of behaviour gives you quite a lot already.