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

Question

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

Answer 1

What I have done if all I want to do is see that some string was logged (as opposed to verifying exact log statements which is just too brittle) is to redirect StdOut to a buffer, do a contains, then reset StdOut:

PrintStream original = System.out;
ByteArrayOutputStream buffer = new ByteArrayOutputStream();
System.setOut(new PrintStream(buffer));

// Do something that logs

assertTrue(buffer.toString().contains(myMessage));
System.setOut(original);

Answer 2

The API for Log4J2 is slightly different. Also you might be using its async appender. I created a latched appender for this:

    public static class LatchedAppender extends AbstractAppender implements AutoCloseable {

    private final List<LogEvent> messages = new ArrayList<>();
    private final CountDownLatch latch;
    private final LoggerConfig loggerConfig;

    public LatchedAppender(Class<?> classThatLogs, int expectedMessages) {
        this(classThatLogs, null, null, expectedMessages);
    }
    public LatchedAppender(Class<?> classThatLogs, Filter filter, Layout<? extends Serializable> layout, int expectedMessages) {
        super(classThatLogs.getName()+"."+"LatchedAppender", filter, layout);
        latch = new CountDownLatch(expectedMessages);
        final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
        final Configuration config = ctx.getConfiguration();
        loggerConfig = config.getLoggerConfig(LogManager.getLogger(classThatLogs).getName());
        loggerConfig.addAppender(this, Level.ALL, ThresholdFilter.createFilter(Level.ALL, null, null));
        start();
    }

    @Override
    public void append(LogEvent event) {
        messages.add(event);
        latch.countDown();
    }

    public List<LogEvent> awaitMessages() throws InterruptedException {
        assertTrue(latch.await(10, TimeUnit.SECONDS));
        return messages;
    }

    @Override
    public void close() {
        stop();
        loggerConfig.removeAppender(this.getName());
    }
}

Use it like this:

        try (LatchedAppender appender = new LatchedAppender(ClassUnderTest.class, 1)) {

        ClassUnderTest.methodThatLogs();
        List<LogEvent> events = appender.awaitMessages();
        assertEquals(1, events.size());
        //more assertions here

    }//appender removed

Answer 3

Wow. I'm unsure why this was so hard. I found I was unable to use any of the code samples above because I was using log4j2 over slf4j. This is my solution:

public class SpecialLogServiceTest {

  @Mock
  private Appender appender;

  @Captor
  private ArgumentCaptor<LogEvent> captor;

  @InjectMocks
  private SpecialLogService specialLogService;

  private LoggerConfig loggerConfig;

  @Before
  public void setUp() {
    // prepare the appender so Log4j likes it
    when(appender.getName()).thenReturn("MockAppender");
    when(appender.isStarted()).thenReturn(true);
    when(appender.isStopped()).thenReturn(false);

    final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
    final Configuration config = ctx.getConfiguration();
    loggerConfig = config.getLoggerConfig("org.example.SpecialLogService");
    loggerConfig.addAppender(appender, AuditLogCRUDService.LEVEL_AUDIT, null);
  }

  @After
  public void tearDown() {
    loggerConfig.removeAppender("MockAppender");
  }

  @Test
  public void writeLog_shouldCreateCorrectLogMessage() throws Exception {
    SpecialLog specialLog = new SpecialLogBuilder().build();
    String expectedLog = "this is my log message";

    specialLogService.writeLog(specialLog);

    verify(appender).append(captor.capture());
    assertThat(captor.getAllValues().size(), is(1));
    assertThat(captor.getAllValues().get(0).getMessage().toString(), is(expectedLog));
  }
}

Answer 4

Mocking is an option here, although it would be hard, because loggers are generally private static final - so setting a mock logger wouldn't be a piece of cake, or would require modification of the class under test.

You can create a custom Appender (or whatever it's called), and register it - either via a test-only configuration file, or runtime (in a way, dependent on the logging framework). And then you can get that appender (either statically, if declared in configuration file, or by its current reference, if you are plugging it runtime), and verify its contents.

Answer 5

As mentioned from the others you could use a mocking framework. For this to make work you have to expose the logger in your class (although I would propably prefere to make it package private instead of creating a public setter).

The other solution is to create a fake logger by hand. You have to write the fake logger (more fixture code) but in this case I would prefer the enhanced readability of the tests against the saved code from the mocking framework.

I would do something like this:

class FakeLogger implements ILogger {
    public List<String> infos = new ArrayList<String>();
    public List<String> errors = new ArrayList<String>();

    public void info(String message) {
        infos.add(message);
    }

    public void error(String message) {
        errors.add(message);
    }
}

class TestMyClass {
    private MyClass myClass;        
    private FakeLogger logger;        

    @Before
    public void setUp() throws Exception {
        myClass = new MyClass();
        logger = new FakeLogger();
        myClass.logger = logger;
    }

    @Test
    public void testMyMethod() {
        myClass.myMethod(true);

        assertEquals(1, logger.infos.size());
    }
}

Answer 6

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