How to do a JUnit assert on a message in a logger

I have some code-under-test that calls on a Java logger to report its status. In the JUnit test code, I would like to verify that the correct log entry was made in this logger. Something along the following lines:

methodUnderTest(bool x){
    if(x)
        logger.info("x happened")
}

@Test tester(){
    // perhaps setup a logger first.
    methodUnderTest(true);
    assertXXXXXX(loggedLevel(),Level.INFO);
}

I suppose that this could be done with a specially adapted logger (or handler, or formatter), but I would prefer to re-use a solution that already exists. (And, to be honest, it is not clear to me how to get at the logRecord from a logger, but suppose that that's possible.)

Solution 1:

I've needed this several times as well. I've put together a small sample below, which you'd want to adjust to your needs. Basically, you create your own Appender and add it to the logger you want. If you'd want to collect everything, the root logger is a good place to start, but you can use a more specific if you'd like. Don't forget to remove the Appender when you're done, otherwise you might create a memory leak. Below I've done it within the test, but setUp or @Before and tearDown or @After might be better places, depending on your needs.

Also, the implementation below collects everything in a List in memory. If you're logging a lot you might consider adding a filter to drop boring entries, or to write the log to a temporary file on disk (Hint: LoggingEvent is Serializable, so you should be able to just serialize the event objects, if your log message is.)

import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LoggingEvent;
import org.junit.Test;

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

import static org.hamcrest.CoreMatchers.is;
import static org.junit.Assert.assertThat;

public class MyTest {
    @Test
    public void test() {
        final TestAppender appender = new TestAppender();
        final Logger logger = Logger.getRootLogger();
        logger.addAppender(appender);
        try {
            Logger.getLogger(MyTest.class).info("Test");
        }
        finally {
            logger.removeAppender(appender);
        }

        final List<LoggingEvent> log = appender.getLog();
        final LoggingEvent firstLogEntry = log.get(0);
        assertThat(firstLogEntry.getLevel(), is(Level.INFO));
        assertThat((String) firstLogEntry.getMessage(), is("Test"));
        assertThat(firstLogEntry.getLoggerName(), is("MyTest"));
    }
}

class TestAppender extends AppenderSkeleton {
    private final List<LoggingEvent> log = new ArrayList<LoggingEvent>();

    @Override
    public boolean requiresLayout() {
        return false;
    }

    @Override
    protected void append(final LoggingEvent loggingEvent) {
        log.add(loggingEvent);
    }

    @Override
    public void close() {
    }

    public List<LoggingEvent> getLog() {
        return new ArrayList<LoggingEvent>(log);
    }
}

Solution 2:

Here is a simple and efficient Logback solution.
It doesn't require to add/create any new class.
It relies on ListAppender : a whitebox logback appender where log entries are added in a public List field that we could so use to make our assertions.

Here is a simple example.

Foo class :

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Foo {

    static final Logger LOGGER = LoggerFactory.getLogger(Foo .class);

    public void doThat() {
        LOGGER.info("start");
        //...
        LOGGER.info("finish");
    }
}

FooTest class :

import org.slf4j.LoggerFactory;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;

public class FooTest {

    @Test
    void doThat() throws Exception {
        // get Logback Logger 
        Logger fooLogger = (Logger) LoggerFactory.getLogger(Foo.class);

        // create and start a ListAppender
        ListAppender<ILoggingEvent> listAppender = new ListAppender<>();
        listAppender.start();

        // add the appender to the logger
        // addAppender is outdated now
        fooLogger.addAppender(listAppender);

        // call method under test
        Foo foo = new Foo();
        foo.doThat();

        // JUnit assertions
        List<ILoggingEvent> logsList = listAppender.list;
        assertEquals("start", logsList.get(0)
                                      .getMessage());
        assertEquals(Level.INFO, logsList.get(0)
                                         .getLevel());

        assertEquals("finish", logsList.get(1)
                                       .getMessage());
        assertEquals(Level.INFO, logsList.get(1)
                                         .getLevel());
    }
}

JUnit assertions don't sound very adapted to assert some specific properties of the list elements.
Matcher/assertion libraries as AssertJ or Hamcrest appears better for that :

With AssertJ it would be :

import org.assertj.core.api.Assertions;

Assertions.assertThat(listAppender.list)
          .extracting(ILoggingEvent::getMessage, ILoggingEvent::getLevel)
          .containsExactly(Tuple.tuple("start", Level.INFO), Tuple.tuple("finish", Level.INFO));

Solution 3:

Thanks a lot for these (surprisingly) quick and helpful answers; they put me on the right way for my solution.

The codebase were I want to use this, uses java.util.logging as its logger mechanism, and I don't feel at home enough in those codes to completely change that to log4j or to logger interfaces/facades. But based on these suggestions, I 'hacked-up' a j.u.l.handler extension and that works as a treat.

A short summary follows. Extend java.util.logging.Handler:

class LogHandler extends Handler
{
    Level lastLevel = Level.FINEST;

    public Level  checkLevel() {
        return lastLevel;
    }    

    public void publish(LogRecord record) {
        lastLevel = record.getLevel();
    }

    public void close(){}
    public void flush(){}
}

Obviously, you can store as much as you like/want/need from the LogRecord, or push them all into a stack until you get an overflow.

In the preparation for the junit-test, you create a java.util.logging.Logger and add such a new LogHandler to it:

@Test tester() {
    Logger logger = Logger.getLogger("my junit-test logger");
    LogHandler handler = new LogHandler();
    handler.setLevel(Level.ALL);
    logger.setUseParentHandlers(false);
    logger.addHandler(handler);
    logger.setLevel(Level.ALL);

The call to setUseParentHandlers() is to silence the normal handlers, so that (for this junit-test run) no unnecessary logging happens. Do whatever your code-under-test needs to use this logger, run the test and assertEquality:

    libraryUnderTest.setLogger(logger);
    methodUnderTest(true);  // see original question.
    assertEquals("Log level as expected?", Level.INFO, handler.checkLevel() );
}

(Of course, you would move large part of this work into a @Before method and make assorted other improvements, but that would clutter this presentation.)

Solution 4:

For Junit 5 (Jupiter) Spring's OutputCaptureExtension is quite useful. Its available since Spring Boot 2.2 and is available in the spring-boot-test artifact.

Example (taken from javadoc):

@ExtendWith(OutputCaptureExtension.class)
class MyTest {
    @Test
    void test(CapturedOutput output) {
        System.out.println("ok");
        assertThat(output).contains("ok");
        System.err.println("error");
    }

    @AfterEach
    void after(CapturedOutput output) {
        assertThat(output.getOut()).contains("ok");
        assertThat(output.getErr()).contains("error");
    }
}

Solution 5:

Effectively you are testing a side-effect of a dependent class. For unit testing you need only to verify that

logger.info()

was called with the correct parameter. Hence use a mocking framework to emulate logger and that will allow you to test your own class's behaviour.