How to test error logs

This is the second part of a series dedicated to testing error logs. Check out my previous post to understand my motivation for asserting in my tests that error logs are actually logged. In this post I’m going to show an example solution using Kotlin, JUnit and logback — but it should be easily extensible to other JVM-based languages.

Context

Before jumping to the solution, we must first review and understand the logging set-up. Logback is one of the most popular logging frameworks, and successor to the also popular log4j framework. It’s also the default logging framework used by Spring Boot, sometimes abstracted under SLF4J. If we take a closer look to logback, it has two key components for our solution:

Logger: contains all the necessary logging context, and allows the application to log messages from a certain location within the code
Appender: writes the logged messages into a destination. For example, the standard output of a console, a text file, a database… it’s even possible to create custom ones

Loggers can have multiple appenders attached, so that the same message is logged to different destinations

Introducing a custom appender

Here’s the idea: since multiple appenders can be attached to a single logger, and it’s possible to implement custom appenders, we can create a fake appender that keeps logs in memory and enables the testing library to perform assertions over them.

In logback, custom appenders can be created by implementing AppenderBase, and using ILoggingEvent as an abstraction for logs emitted by a logger:

kotlin

FakeAppender.kt

import ch.qos.logback.classic.spi.ILoggingEvent
import ch.qos.logback.core.AppenderBase
import java.util.Collections.synchronizedList

class FakeAppender: AppenderBase<ILoggingEvent>() {
    private val loggingEvents: MutableList<ILoggingEvent> = synchronizedList(mutableListOf())

    override fun append(eventObject: ILoggingEvent) {
        loggingEvents.add(eventObject)
    }
}

Using FakeAppender in the tests

JUnit extensions to the rescue! We can create a custom extension using ParameterResolver to inject the fake appender into the test method as a parameter. Since we only need to record logs during the test run, we can start and stop the appender before and after each test method is executed, respectively, using BeforeEachCallback and AfterEachCallback:

kotlin

LoggingCaptorExtension.kt

import org.junit.jupiter.api.extension.AfterEachCallback
import org.junit.jupiter.api.extension.BeforeEachCallback
import org.junit.jupiter.api.extension.ExtensionContext
import org.junit.jupiter.api.extension.ParameterContext
import org.junit.jupiter.api.extension.ParameterResolver

class LoggingCaptorExtension: BeforeEachCallback, AfterEachCallback, ParameterResolver {
    private lateinit var fakeAppender: FakeAppender

    override fun beforeEach(context: ExtensionContext) {
        fakeAppender = FakeAppender()
        fakeAppender.start()
    }

    override fun afterEach(context: ExtensionContext) {
        fakeAppender.stop()
    }

    override fun supportsParameter(parameterContext: ParameterContext, extensionContext: ExtensionContext): Boolean {
        return FakeAppender::class.java == parameterContext.parameter.type
    }

    override fun resolveParameter(parameterContext: ParameterContext, extensionContext: ExtensionContext): Any {
        return fakeAppender
    }
}

Attaching FakeAppender to the relevant loggers

You might have noticed that we never attached the fake appender to any logger. That means that it will never receive any logging events! How could we attach it to all the relevant loggers under test? As we don’t/can’t know which loggers will be used during a test run, the best bet is to attach it to all loggers. Luckily there’s an easy way to do that: there is a root logger at the top of the logger hierarchy, and any appender attached to it will be attached to all loggers. Let’s revisit the LoggingCaptorExtension implementation:

kotlin

LoggingCaptorExtension.kt

import ch.qos.logback.classic.Logger
import org.junit.jupiter.api.extension.AfterEachCallback
import org.junit.jupiter.api.extension.BeforeEachCallback
import org.junit.jupiter.api.extension.ExtensionContext
import org.junit.jupiter.api.extension.ParameterContext
import org.junit.jupiter.api.extension.ParameterResolver
import org.slf4j.LoggerFactory

class LoggingCaptorExtension: BeforeEachCallback, AfterEachCallback, ParameterResolver {
    private val rootLogger: Logger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME) as Logger
    private lateinit var fakeAppender: FakeAppender

    override fun beforeEach(context: ExtensionContext) {
        fakeAppender = FakeAppender()
        fakeAppender.start()
        rootLogger.addAppender(fakeAppender)
    }

    override fun afterEach(context: ExtensionContext) {
        fakeAppender.stop()
        rootLogger.detachAppender(fakeAppender)
    }

    override fun supportsParameter(parameterContext: ParameterContext, extensionContext: ExtensionContext): Boolean {
        return FakeAppender::class.java == parameterContext.parameter.type
    }

    override fun resolveParameter(parameterContext: ParameterContext, extensionContext: ExtensionContext): Any {
        return fakeAppender
    }
}

Testing error logs, in practice

Now we have all the pieces for our solution to work. Let’s add a helper method to FakeAppender so we can make assertions against the stored error messages:

kotlin

FakeAppender.kt

import ch.qos.logback.classic.Level
import ch.qos.logback.classic.spi.ILoggingEvent
import ch.qos.logback.core.AppenderBase
import java.util.Collections.synchronizedList

class FakeAppender: AppenderBase<ILoggingEvent>() {
    private val loggingEvents: MutableList<ILoggingEvent> = synchronizedList(mutableListOf())

    override fun append(eventObject: ILoggingEvent) {
        loggingEvents.add(eventObject)
    }

    fun hasLoggedError(message: String): Boolean {
        return loggingEvents
            .filter { it.level == Level.ERROR }
            .any { it.message == message }
    }
}

And now let’s pretend this is a bit of code that logs an important error:

kotlin

import org.slf4j.LoggerFactory

class SomeInnocentClass {

    fun aMethodThatMightLogErrors(beAngry: Boolean) {
        if (beAngry) {
            LOG.error("Aargh!! That is enough!")
        }
    }

    companion object {
        private val LOG = LoggerFactory.getLogger(SomeInnocentClass::class.java)
    }
}

It’s a critical log that will allow the developers to quickly discover and fix a possible misbehaviour, so we need to test it out!

kotlin

import com.dmalaminos.testingErrorLogs.FakeAppender
import com.dmalaminos.testingErrorLogs.LoggingCaptorExtension
import com.dmalaminos.testingErrorLogs.SomeInnocentClass
import org.junit.jupiter.api.assertions.assertTrue
import org.junit.jupiter.api.assertions.assertFalse
import org.junit.jupiter.api.Test
import org.junit.jupiter.api.extension.ExtendWith

class SomeInnocentClassTest {

    @Test
    @ExtendWith(LoggingCaptorExtension::class)
    fun `angry error is logged`(appender: FakeAppender) {
        val someInnocentClass = SomeInnocentClass()
        someInnocentClass.aMethodThatMightLogErrors(beAngry = true)
        assertTrue(appender.hasLoggedError("Aargh!! That is enough!"))
    }

    @Test
    @ExtendWith(LoggingCaptorExtension::class)
    fun `angry error is not logged`(appender: FakeAppender) {
        val someInnocentClass = SomeInnocentClass()
        someInnocentClass.aMethodThatMightLogErrors(beAngry = false)
        assertFalse(appender.hasLoggedError("Aargh!! That is enough!"))
    }
}

Summary

Here’s what happens, step by step:

LoggingCaptorExtension attaches FakeAppender to the root logger before running every annotated test, and injects it into the test method
The test method executes the code from some class that uses a logger for logging error messages
All logged messages are appended to the in-memory store of the fake appender
The test method performs assertions over the stored logs, either passing or failing
LoggingCaptorExtension detaches FakeAppender from the root logger as the test finishes its execution

Components used for testing logs, and how they interact with each other

We can even extend FakeAppender with methods to test formatted error logs, or error logs with a certain exception attached:

kotlin

FakeAppender.kt

fun hasLoggedError(message: String, vararg parameters: Any): Boolean {
    val formattedMessage = MessageFormatter.arrayFormat(message, parameters).message
    return loggingEvents
        .filter { it.level == Level.ERROR }
        .any { it.formattedMessage == formattedMessage }
}

fun <T: Throwable> hasLoggedError(message: String, exceptionType: KClass<T>): Boolean {
    return loggingEvents
        .filter { it.level == Level.ERROR }
        .any { it.message == message && it.throwableProxy.className == exceptionType.qualifiedName }
}

Now you only need to craft your error log and react to it, when the time comes. Happy testing!

Published on March 11, 2024