Logging testen – mit einer eigenen JUnit-Extension

Logging testen

Loggen ist wichtig. In Einzelfällen sogar so wichtig, dass man ggf. testen möchte, ob bestimmte Ereignisse von der Anwendung korrekt geloggt werden. Hierfür gibt es unterschiedliche Ansätze. Zum Beispiel könnte man den Logger einer Klasse durch einen Mock ersetzen, anhand dessen verifiziert wird, ob die gewünschten Log-Methoden aufgerufen wurden. Doch damit verändert man das Logging-Verhalten der getesteten Klasse, und die während des Tests erzeugten Lognachrichten werden „verschluckt“, d.h. sie landen nicht im üblichen Ausgabemedium (Konsole, Datei o.ä.). Zudem ist das Ersetzen eines Loggers durch einen Mock in vielen Fällen nicht bzw. nur mit unschönen Hacks möglich, da Logger oft static und final deklariert werden.

Daher wählen wir einen anderen Ansatz. Und zwar fügen wir dem Root-Logger einfach einen Appender hinzu, der alle geloggten Events aufzeichnet. Damit kann später geprüft werden, ob die gewünschten Log-Events vorhanden sind.

Die JUnit-Extension

Doch zuerst wollen wir die Grundlage schaffen, nämlich die JUnit-Extension. Hierfür stellt JUnit 5 uns eine Reihe von Callback-Interfaces zur Verfügung:

• BeforeAllCallback
• BeforeEachCallback
• BeforeTestExecutionCallback
• AfterTestExecutionCallback
• AfterEachCallback
• AfterAllCallback
• TestInstancePreDestroyCallback

Der erfahrene Unit-Tester erkennt natürlich sofort den Bezug zum Lebenszyklus eines JUnit-Tests. Alles was wir tun müssen, ist ein oder mehrere dieser Interfaces in einer Klasse zu implementieren – und schon haben wir unsere JUnit-5-Extension!

Für unsere Logging-Extension verwenden wir BeforeTestExecutionCallback und AfterTestExecutionCallback:

public class AssertLoggedExtension implements BeforeTestExecutionCallback, AfterTestExecutionCallback {
  
    @Override
    public void beforeTestExecution(ExtensionContext context) {
        // ...
    }

    @Override
    public void afterTestExecution(ExtensionContext context) {
        // ...
    }
}

Wie der Name schon sagt wird die Methode des ersten Interfaces, „beforeTestExecution(…)“ vor Ausführung der Testmethode aufgerufen. Hier fügen wir unseren Appender hinzu (dafür verwenden wir die selbstimplementierte Klasse ListAppender, die alle empfangenen Events in einer ArrayList speichert):

    private final ListAppender listAppender = new ListAppender();

    @Override
    public void beforeTestExecution(ExtensionContext context) {
        Logger rootLogger = (Logger) LogManager.getRootLogger();
        rootLogger.addAppender(listAppender);
    }

Nach der Testausführung (Methode „afterTestExecution(…)“) entfernen wir den Appender wieder und löschen außerdem die geloggten Events:

    @Override
    public void afterTestExecution(ExtensionContext context) {
        Logger rootLogger = (Logger) LogManager.getRootLogger();
        rootLogger.removeAppender(listAppender);
        listAppender.clearLogEvents();
    }

Zuletzt fügen wir unserer Extension noch Methoden hinzu, mit denen wir testen können, ob die Anwendung wie gewünscht geloggt hat:

    public void info(String expectedMessage) {
        assertLogged(expectedMessage, Level.INFO);
    }

    // more methods for the other log levels

    private void assertLogged(String message, Level level) {
        listAppender.getLoggedEvents().stream()
            .filter(e -> e.getLevel().equals(level))
            .filter(e -> e.getMessage().getFormattedMessage().equals(message))
            .findAny()
            .orElseThrow(() -> new AssertionFailedError("Log message '" + message + "' with level '" + level + 
                                                        "' was expected, but not logged."));
    }

Verwenden der Extension

Nun zur Verwendung unserer Extension im Test. Hierfür gibt es zwei Möglichkeiten:

• Mit der Annotation @ExtendWith über der Testklassendefinition
• Via @RegisterExtension innerhalb der Testklasse

Da wir direkt mit unserer Extension interagieren möchten, indem wir die Prüfmethoden aufrufen, benötigen wir Variante Nr. 2:

public class AppTest {

    @RegisterExtension
    static final AssertLoggedExtension assertLogged = new AssertLoggedExtension();

    // ...
}

Jetzt fehlen nur noch das zu testende Objekt und die Testmethode. Damit sieht unsere Testklasse wie folgt aus:

public class AppTest {

    @RegisterExtension
    static final AssertLoggedExtension assertLogged = new AssertLoggedExtension();

    // subject under test
    private final App app = new App();

    @Test
    public void shouldHaveLogged() {
        app.run();

        assertLogged.info("Running");
    }
}

Hier wird ersichtlich, wieso die Instanz unserer Extension „assertLogged“ genannt wurde: So ergibt sich gut lesbarer und verständlicher Testcode.

Und das war’s auch schon! Wir haben unsere Extension, mit der wir Logging testen können. War doch gar nicht schwer, oder?

Der komplette Quellcode des Beispiels ist auf GitHub unter https://github.com/doubleSlashde/assert-log zu finden.

Zwei Anmerkungen zum Schluss:

• Der Einfachheit halber habe ich mich auf das Logging-Framework Log4j2 beschränkt. Mit logunit gibt es eine Extension, die mehrere Logframeworks unterstützt.
• Die Extension funktioniert nicht bei paralleler Ausführung der Tests. Dies liegt daran, dass die Logkonfiguration global ist und durch die Extension ständig überschrieben würde. Ist parallele Ausführung zwingend erforderlich, muss auf die oben beschriebene Variante mit dem Mocken von Loggern zurückgegriffen werden.

Mehr über Softwareentwicklung erfahren