Search code examples
javaunit-testingmockitologbackslf4j

How to ignore/mock Slf4j log lines?

I upgraded Spring Boot from 2.5.10 to 2.5.12 and it brought a breaking change for me in logback https://github.com/spring-projects/spring-boot/releases/tag/v2.5.11

A few of my unit tests (using Mockito) are breaking with NullPointerException where I am passing a mocked exception to the log lines in the main code. For example, this is a log line that I have in my main code, and the class is annotated with lombok's @Slf4j

log.warn("Exception occurred while doing something", exception);

Earlier, this log line was not throwing any errors.

My intention here is to not mock the logger, but to ignore this line through whatever workaround possible (even if I have to mock it).

Lombok adds the following on compilation (not sure if mocking would work here):

private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(HelloWorld.class);

One workaround I have is to not use mocked exceptions and pass an actual exception but that's going to take the fun out of unit tests.

Stack trace:

java.lang.NullPointerException
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:99)
    at ch.qos.logback.classic.spi.ThrowableProxy.<init>(ThrowableProxy.java:62)
    at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
    at ch.qos.logback.classic.Logger.warn(Logger.java:692)
    at com.example.r.e.d.s.d.t.HelloWorld.executeInternal(HelloWorld.java:74)
    at com.example.r.e.d.s.d.t.HelloWorldTest.testLocksOnDomain(HelloWorldTest.java:94)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    at org.mockito.internal.runners.DefaultInternalRunner$1$1.evaluate(DefaultInternalRunner.java:54)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
    at org.mockito.internal.runners.DefaultInternalRunner$1.run(DefaultInternalRunner.java:99)
    at org.mockito.internal.runners.DefaultInternalRunner.run(DefaultInternalRunner.java:105)
    at org.mockito.internal.runners.StrictRunner.run(StrictRunner.java:40)
    at org.mockito.junit.MockitoJUnitRunner.run(MockitoJUnitRunner.java:163)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
    at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
    at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:235)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)


Process finished with exit code 255

Moreover, with my unit tests working with the previous library version. There was a problem that during the execution of the unit tests, it used to print logs like WARN and ERROR in the console (which sometimes created a lot of confusion).

Solution

  • The line responsible for the error (in the version that you mentioned) looks like this (see https://github.com/qos-ch/logback/blob/v_1.2.11/logback-classic/src/main/java/ch/qos/logback/classic/spi/ThrowableProxy.java#L99):

    if (throwableSuppressed.length > 0) {

    It's worth noting that there's a fix for your issue, although I have no idea what version of Logback might have it now or in the future. https://github.com/qos-ch/logback/commit/c34645b320d2b31ccaf0de9bb079391904352a28 contains the following relevant change: Replaced

    if (throwableSuppressed.length > 0) {

    with

    // while JDK's implementation of getSuppressed() will always return a non-null array,
// this might not be the case in mocked throwables. We are being extra defensive here.
if (OptionHelper.isNotEmtpy(throwableSuppressed)) {

    I'm generally not super keen on mocking Exceptions, myself. But if that's what your context demands, then mocking getSuppressed() to return a non-null (probably empty is fine) array might solve the issue.