Integration Tests in a Cloud Foundry Java App using Logging

During development of our Cloud Foundry Java app we sometimes came to a point where we ned to check if correct application logs are written. We also wanted to knwo if somethings happends in a correct thread.

In this blog post I will explain what needs to be done to check for correct logs.

Our Service Setup

• Java 8 application
• Build tool: maven
• Spring Boot 2.x.x
• Logger
  • Dependency: org.slf4j:slf4j-api:1.7.29

Add Appender to Logger

To have the possibility to check what was logged we need to find a way to get the written logs in the test. Therefor a possibility exists to extend the logger by an appender which can later be used to retrieve the logging events.

The appender can be added to the logger like this:

    @Mock
    private Appender<ILoggingEvent> appender;

    @Before
    public void setup() {
        LOGGER.addAppender(appender);
    }

The logger in this case needs to be the logger from the class where the logs are written. The logger can be created like this:

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

Here the logger of the class ProductiveImplementation is used. Now all logs written in this class can be retrieved by the appender.

Read log entries from appender

After this was added the productive coding can be called. After the logs are written the written logs can be captured. For this a log captor needs to be created:

    @Captor
    private ArgumentCaptor<ILoggingEvent> logCaptor;

Using mockito the captor can be used to retrieve the logs:

verify(appender, times(1)).doAppend(logCaptor.capture());

This line does two things:

1. It checks if the appender was only called once. That means in the test we only expect one log entry.
2. For the method doAppend it capture the written log evnets in the logCaptor

From the logCaptor the events can be retrieved and from the events several properties like formatted message, arguments and so on can be retrieved and used in checks in the test.

Attention should be payed to the not all logs are captured but only message of the following types:

• error
• warning
• info

Check Logger is called in correct thread

With the logic to read entries from the logCaptor it could also be checked that the log was called in the correct thread. If the log was called in an asynchronously task the verify needs to be enhanced a little bit:

verify(appender, timeout(500).times(1)).doAppend(logCaptor.capture());

Here a timeout was introduced. The verify will check in the time till the timeout recurring if the method of the appender was called. So if the method is called after 5 milliseconds the test will not wait till the 500 milliseconds are done.

If in this time the method is not called the test failed.

Now after the logs are catured the events can be retrieved like before. With the retrieved events validations like this can be written:

assertThat(event.getThreadName()).isNotEqualTo(Thread.currentThread()
                                                     .getName());

Complete Test example

package com.sap.testapp;

import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.Appender;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.ArgumentCaptor;
import org.mockito.Captor;
import org.mockito.Mock;
import org.slf4j.LoggerFactory;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringRunner;

import java.util.List;

import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Mockito.*;

@RunWith(SpringRunner.class)
@SpringBootTest
public class LoggingIT {

    private static final String TEST_MESSAGE = "some test message";

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

    @Mock
    private Appender<ILoggingEvent> appender;
    @Captor
    private ArgumentCaptor<ILoggingEvent> logCaptor;

    @Before
    public void setup() {
        LOGGER.addAppender(appender);
    }

    @Test
    public void logsAreCaptured() {
        logSomeText(); //needs to be replaced by the productive coding call

        ILoggingEvent event = getLoggingEvent();

        assertThat(event.getMessage()).isEqualTo(TEST_MESSAGE);
        assertThat(event.getThreadName()).isEqualTo(Thread.currentThread().getName());

    }

    private void logSomeText() {
        LOGGER.info(TEST_MESSAGE);
        LOGGER.debug("other message");
    }

    private ILoggingEvent getLoggingEvent() {
        verify(appender, timeout(500).times(1)).doAppend(logCaptor.capture());
        List<ILoggingEvent> loggingEvents = logCaptor.getAllValues();

        return loggingEvents.get(0);
    }

}

Conclusion

In this blog post I showed how to test log entries in integration test. It is very easy to test such entries written in productive coding.

How much it makes sense to test the concrete message within the logs depends on the requirenment of the test. Sometimes the message is important to test other times only the parameters given to the message are relevant.

We also saw how to check the thread in which the log was written and also how to wait for asynchronously threads.

Back to overview