SLF4J Test

Making Assertions

TestLoggerFactory is the underlying implementation to which SLF4J's LoggerFactory delegates when SLF4J Test is the bound SLF4J implementation. The getLogger method on TestLoggerFactory returns the same Logger instance as that on LoggerFactory, but with the additional type information to allow retrieval of the LoggingEvents that have occurred against that Logger.

SLF4J Test provides a comprehensive set of static factory methods on LoggingEvent to facilitate easy construction of expected events for comparison against those that were actually received, and LoggingEvent has appropriate equals, hashCode and toString implementations for this purpose. See the front page for an example of using the info static factory method to create an expected LoggingEvent.

assertThat(logger)
    .hasLogged(event -> event.getFormattedMessage().startsWith("First section of long log message"));

assertThat(logger)
    .usingMdcComparator(MdcComparator.IGNORING)
    .hasLogged(warn("Some log message"));

Setting the Log Level on a Logger

SLF4J Test only stores events for levels which are marked as enabled on the Logger. By default, all levels are enabled; however, this can be programmatically changed on a per logger basis using the following functions:

Logger.setEnabledLevels(Level... levels)
Logger.setEnabledLevelsForAllThreads(Level... levels)

It's important to note that SLF4J does not imply any relationship between the levels - it is perfectly possible for a logger to be enabled for INFO but disabled for ERROR as far as SLF4J is concerned, and hence as far as SLF4J Test is concerned, notwithstanding the fact that implementations such as Logback and Log4J do not permit this.

Globally disabling a Log Level

Storing log events at all levels can slow down test executions. If needed a global setting can be used to avoid capturing events at a given level or below respecting the conventional level hierarchy (if the capture level is set to INFO, DEBUG and TRACE events won't be captured). This can be set in any of the following ways:

TestLoggerFactory.getInstance().setCaptureLevel(Level.INFO);

-Dslf4jtest.capture.level=INFO

capture.level=INFO

Resetting Stored State

In order to have robust tests the in memory state of SLF4J Test must be in a known state for each test run, which in turn implies that a test should clean up after itself. The simplest way to do so is via a call to

TestLoggerFactory.clear()

in a tear down method of some kind.

More nuanced state resetting can be done on a per logger basis:

TestLogger.clear()

or more aggressive clears will reset state across all threads:

TestLoggerFactory.clearAll()
TestLogger.clearAll()

@Rule public TestRule resetLoggingEvents = new TestLoggerFactoryResetRule();

import org.junit.jupiter.api.extension.ExtendWith;
import com.github.valfirst.slf4jtest.TestLoggerFactoryExtension;

@ExtendWith(TestLoggerFactoryExtension.class)
class BasicJUnit5Test {
    ...
}

import org.junit.jupiter.api.extension.ExtendWith;
import com.github.valfirst.slf4jtest.CleanupStage;
import com.github.valfirst.slf4jtest.TestLoggerFactoryExtension;
import com.github.valfirst.slf4jtest.TestLoggerFactorySettings;

@ExtendWith(TestLoggerFactoryExtension.class)
@TestLoggerFactorySettings(cleanupStage = CleanupStage.BEFORE_EACH)
class BasicJUnit5Test {
    ...
}

import org.junit.jupiter.api.extension.RegisterExtension;
import com.github.valfirst.slf4jtest.TestLoggerFactoryExtension;

class BasicJUnit5Test {

    @RegisterExtension
    static TestLoggerFactoryExtension extension = new TestLoggerFactoryExtension();
    ...
}

import org.junit.jupiter.api.extension.RegisterExtension;
import com.github.valfirst.slf4jtest.CleanupStage;
import com.github.valfirst.slf4jtest.TestLoggerFactoryExtension;

class BasicJUnit5Test {

    @RegisterExtension
    static TestLoggerFactoryExtension extension = new TestLoggerFactoryExtension(CleanupStage.BEFORE_EACH);
   ...
}

Parallel Testing

SLF4J Test is designed to facilitate tests run in parallel. Because SLF4J Loggers are commonly shared across threads, the SLF4J Test implementation maintains its state in ThreadLocals. The following functions:

TestLogger.getLoggingEvents()
TestLogger.clear()
TestLogger.getEnabledLevels()
TestLogger.setEnabledLevels(Level... levels)
TestLoggerFactory.getLoggingEvents()
TestLoggerFactory.clear()

all only affect state stored in a ThreadLocal, and thus tests which use them can safely be parallelised without any danger of concurrent test runs affecting each other.

Testing Multiple Threads Logging

At times, however, it may be desirable to assert about the log messages produced by concurrent code. To facilitate this SLF4J Test also maintains a record of logging events from all threads. This state can be accessed and reset using the following functions:

TestLogger.getAllLoggingEvents()
TestLogger.clearAll()
TestLogger.setEnabledLevelsForAllThreads(Level... levels)
TestLoggerFactory.getAllLoggingEvents()
TestLoggerFactory.clearAll()

Printing log statements to System out and err

It can still be useful to print log messages to System out/err as appropriate. SLF4J Test will print messages using a standard (non-configurable) format based on the value of the TestLoggerFactory's printLevel property. For convenience this does respect the conventional level hierarchy where if the print level is INFO logging events at levels WARN and ERROR will also be printed. A level that is disabled globally will not be printed.

This can be set in any of the following ways:

TestLoggerFactory.getInstance().setPrintLevel(Level.INFO);

-Dslf4jtest.print.level=INFO

print.level=INFO

Testing Code Using java.util.logging

Although this module is named SLF4J Test, it can be used to test code using other test API's as well. In most cases, it is just a matter of placing the proper bridge on the test classpath, see e.g. Bridging legacy APIs. But in case of java.util.logging, there is a little more work than adding jul-to-slf4j to the classpath. Normally, an application will create a logging.properties file containing

handlers = org.slf4j.bridge.SLF4JBridgeHandler

and set the system property java.util.logging.config.file on the command line to the full path of the file. But this is not practical for running unit tests. Instead, the configuration is done programmatically in the test code.

SLF4J Test has code to make this easier. Calling JulConfig.setup() will do this for you. You should call this method before running any test that requires java.util.logging to be configured. Calling this method more than once has no effect, so you can safely call it before tests in all test suites with this requirement, e.g. in a @BeforeClass method if using Junit 4.

If you use Junit 5, it is even easier. There is a Junit 5 extension JulConfigExtension doing this declaratively. For example

import com.github.valfirst.slf4jtest.JulConfigExtension;
import org.junit.jupiter.api.extension.ExtendWith;

@ExtendWith(JulConfigExtension.class)
class JulLoggingTests {
    @Test
    void testJulLogging() {
        ...
    }
    ...
}

Customizing the MDC

The MDC (original meaning Mapped Diagnostic Context) is a place that can be used to store additional information as key/value pairs. The information is stored by thread. It can be set by the client code and used by the logging backend. The specification of the MDC in SLF4J leaves much detail up to the logging backend.

SLF4J Test lets the user customize the behavior of the MDC to more closely match that of the backend expected to be used at run-time.

The configuration can be changed in the property file slf4jtest.properties, using system properties specified as command line arguments to the JVM, or programmatically. The property file and the system properties are read at start-up time, with system properties overriding the property file. Note that changing the values programmatically affects all threads.

TestMDCAdapter.getInstance().setEnable(false);

-Dslf4jtest.mdc.enable=false

mdc.enable=false

TestMDCAdapter.getInstance().setInherit(true);

-Dslf4jtest.mdc.inherit=true

mdc.inherit=true

TestMDCAdapter.getInstance().setAllowNullValues(false);

-Dslf4jtest.mdc.allow.null.values=false

mdc.allow.null.values=false

TestMDCAdapter.getInstance().setReturnNullCopyWhenMdcNotSet(true);

-Dslf4jtest.mdc.return.null.copy.when.mdc.not.set=true

mdc.return.null.copy.when.mdc.not.set=true

TestMDCAdapter.getInstance().restoreOptions();

Using the Fluent API

From SLF4J version 2.0, there is a new fluent logging API. It allows writing code like

logger.atInfo().setMessage("With an argument {}")
    .addArgument(() -> myObj.calculateValue())
    .addMarker("ForYourEyesOnly").log();

The atInfo() method returns a LoggingEventBuilder which is used to build the event and finally log it.

If logging at INFO level is not enabled, a NOOP LoggingEventBuilder is returned by atInfo. This means the lambda on the second line will not be executed, thus saving the overhead if the message is not logged.

Note that it is possible to add multiple markers to an event, which is not possible with the classic API.

SLF4J Test uses the TestLoggingEventBuilder, which is a modified version of the DefaultLoggingEventBuilder of SLF4J.

Creating an SLF4J Test LoggingEvent to compare against can be done in the classic way like

LoggingEvent.info(
    MarkerFactory.getMarker("ForYourEyesOnly"),
    "With an argument {}",
    myObj.calculateValue());

Alternatively, you can create the LoggingEvent from an existing SLF4J logging event, like

LoggingEvent.fromSlf4jEvent(
    new TestLoggingEventBuilder(null, Level.INFO)
        .setMessage("With an argument {}")
        .addArgument(() -> myObj.calculateValue())
        .addMarker(MarkerFactory.getMarker("ForYourEyesOnly"))
        .toLoggingEvent());

This approach is necessary if you use the features available in the fluent API only. This includes multiple markers and key/value pairs.

The TestLoggingEventBuilder adds the toLoggingEvent method to access the created event. Please note that the returned value is an org.slf4j.event.LoggingEvent, which is different from com.github.valfirst.slf4jtest.LoggingEvent.