Unit-Tests für Logger

26.05.2016

Unit-Tests für Logger mit Mockito und PowerMock

In diesem Artikel wird beschrieben, wie man Variablen für JUnit-Tests mocken kann, die private static final sind. Unter anderem kann man auf diese Weise auch testen, ob Log-Ausgaben mit Log4J oder SLF4J geschrieben wurden ohne die Logdatei selbst untersuchen zu müssen. Um das zu erreichen wird Mockito und PowerMock verwendet und eine Methode, um mittels der Reflection-API, das final zu entfernen, damit Mockito die Variable durch ein Mock-Objekt ersetzen kann.

Getestet werden soll die folgende Klasse:

import org.slf4j.Logger;

/**
 * Created by hameister on 26.05.16.
 */
public class ProcessLogger {

    private static final Logger LOGGER = 
          (Logger) org.slf4j.LoggerFactory.getLogger(ProcessLogger.class);


    public void startProcess() {

        LOGGER.info("Start Process");
        // Step 1
        LOGGER.info("Step 1");

        // Some calculations
        LOGGER.debug("Debug Message Step 1");

        // Step 2
        LOGGER.info("Step 2");

        // Error Handling
        LOGGER.error("Error Step 2");

        // Step 3
        LOGGER.info("Step 3");

        // Finished Process
        LOGGER.info("Finished Process");
    }
}

In der Klasse ProcessLogger wurden der Übersichtlichkeit wegen die BusinessLogik entfernt. Es befinden sich nur noch die Log-Ausgaben in der Methode startProcess(); Und genau um diese Log-Ausgaben geht es bei dem Test. Es soll überprüft werden, ob das Logging fehlerfrei funktioniert. Dabei soll keine Log-Datei geladen werden, sondern direkt in die Variable LOGGER überprüft werden, ob und mit welchem String sie aufgerufen wird. Das "schwierige" dabei ist, dass die Variable private static und final ist, d.h. nur mit JUnit und Mockito kommt man nicht weiter. Um statische Variablen zu mocken und zu testen kann PowerMock verwendet werden. Damit das im Zusammenspiel mit Mockito funktioniert, muss allerdings noch das final über die Reflection-API geändert werden. Wie das funktioniert, zeigt folgende Testklasse:

import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.mockito.ArgumentCaptor;
import org.mockito.InjectMocks;
import org.mockito.MockitoAnnotations;
import org.powermock.core.classloader.annotations.PrepareForTest;
import org.powermock.modules.junit4.PowerMockRunner;
import org.slf4j.Logger;

import java.lang.reflect.Field;
import java.lang.reflect.Modifier;
import java.util.List;

import static org.hamcrest.CoreMatchers.is;
import static org.junit.Assert.assertThat;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.powermock.api.mockito.PowerMockito.mockStatic;

/**
 * Created by hameister on 26.05.16.
 */

@RunWith(PowerMockRunner.class)
@PrepareForTest({Logger.class})
public class ProcessLoggerTest {

    @InjectMocks
    ProcessLogger processLogger;

    Logger logger;

    @Before
    public void before() throws Exception {
        mockStatic(Logger.class);
        logger = mock(Logger.class);
        MockitoAnnotations.initMocks(this);

        // Set logger to NOT final
        changeAccessability(ProcessLogger.class.getDeclaredField("LOGGER"), logger);
    }

    public static void changeAccessability(Field field, Object newValue) throws Exception {
        field.setAccessible(true);

        Field modifiersField = Field.class.getDeclaredField("modifiers");
        modifiersField.setAccessible(true);
        modifiersField.setInt(field, field.getModifiers() & ~Modifier.FINAL);

        field.set(null, newValue);
    }

    @Test
    public void processShouldWriteLogs(){

        ArgumentCaptor<String> logEntry = ArgumentCaptor.forClass(String.class);

        processLogger.startProcess();
        verify(logger, times(5)).info(logEntry.capture());
        verify(logger, times(1)).debug(logEntry.capture());
        verify(logger, times(1)).error(logEntry.capture());
        verify(logger, times(0)).warn(logEntry.capture());

        List<String> logMessages =logEntry.getAllValues();

        //Test info
        assertThat(logMessages.get(0), is("Start Process"));
        assertThat(logMessages.get(1), is("Step 1"));
        assertThat(logMessages.get(2), is("Step 2"));
        assertThat(logMessages.get(3), is("Step 3"));
        assertThat(logMessages.get(4), is("Finished Process"));

        //Test debug
        assertThat(logMessages.get(5), is("Debug Message Step 1"));

        //Test error
        assertThat(logMessages.get(6), is("Error Step 2"));

    }
}

Als Runner wird @RunWith(PowerMockRunner.class), der Bestandteil von PowerMock ist verwendet. Mit einer @Rule sollte es aber auch funktionieren.

Mit @PrepareForTest({Logger.class}) wird erreicht, dass die statische Variable LOGGER aus der Klasse ProcessLogger gemockt werden kann.

Mit @InjectMocks wird festgelegt, dass die Mocks für die Klasse ProcessLogger verwendet werden.

In der Methode before() werden die Mocks erst mit mockStatic und mock vorbereitet und anschliessend mit MockitoAnnotations.initMocks(this); in die Klasse ProcessLog eingefügt.

Abschliessend wird in der Methode changeAccessability die Variable LOGGER auf public und das final auf false gesetzt.

Jetzt ist alles soweit vorbereitet, dass der eigentlich Unit-Test erstellt werden kann.

Der ArgumentCaptor wird dazu verwendet, um zu überprüfen, mit welchem String-Wert der Logger aufgerufen wird.

Nachdem die Methode processLogger.startProcess(); ausgeführt wurde. Kann mit verify überprüft werden, wie oft die Log-Methoden (info, debug, error, warn) des Logger aufgerufen wurden.

Anschliessend werden alle Log-Meldungen mit logEntry.getAllValues(); in einer Liste zwischengespeichert und der Reihe nach auf ihren Wert hin überprüft.

Zu beachten ist, dass die Reihenfolge der Log-Ausgaben in der Liste abhängig von der Reihenfolge der capture-Aufrufe beim verify ist.

Am einfachsten legt man zum Testen ein Maven-Projekt mit folgender pom-Datei an, die alle notwendigen Bibliotheken enthält.

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>org.hameister.ProcessLogger</groupId>
    <artifactId>ProcessLogger</artifactId>
    <version>1.0-SNAPSHOT</version>


    <dependencies>

        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.1.7</version>
        </dependency>

        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-core</artifactId>
            <version>1.1.7</version>
        </dependency>


        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.12</version>
            <scope>test</scope>
        </dependency>

        <dependency>
            <groupId>org.hamcrest</groupId>
            <artifactId>hamcrest-core</artifactId>
            <version>1.3</version>
        </dependency>

        <dependency>
            <groupId>org.hamcrest</groupId>
            <artifactId>hamcrest-library</artifactId>
            <version>1.3</version>
        </dependency>

        <dependency>
            <groupId>org.mockito</groupId>
            <artifactId>mockito-core</artifactId>
            <version>1.10.19</version>
        </dependency>

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.21</version>
        </dependency>


        <dependency>
            <groupId>org.powermock</groupId>
            <artifactId>powermock-api-mockito</artifactId>
            <version>1.6.5</version>
        </dependency>


        <dependency>
            <groupId>org.powermock</groupId>
            <artifactId>powermock-module-junit4</artifactId>
            <version>1.6.5</version>
        </dependency>
    </dependencies>

</project>