Spock unit testing assert log calls and see output

Question

I am using spock to test Java Spring Boot code. It gets a logback logger over the lombok @Slf4j annotation.

Dummy class with log call

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

@Slf4j
@Component
public class Clazz {

  public void method() {
    // ... code
    log.warn("message", new RuntimeException());
  }
}

The Spock Spec

import groovy.util.logging.Slf4j
import org.junit.Rule
import org.slf4j.Logger
import spock.lang.Specification

@Slf4j
class LogSpec extends Specification {

  Clazz clazz = new Clazz()

  private Logger logger = Mock(Logger.class)

  @Rule
  ReplaceSlf4jLogger replaceSlf4jLogger = new ReplaceSlf4jLogger(Clazz, logger)

  def "warning ia logged"() {

    given: "expected message"

    when: "when calling the method"
    clazz.method()

    then: "a warning is logged"
    1 * logger.warn(_, _) >> {
      msg, ex -> log.warn(msg, ex)
    }
  }
}

Helper to switch the real with the mock logger taken from this answer.

import org.junit.rules.ExternalResource
import org.slf4j.Logger

import java.lang.reflect.Field
import java.lang.reflect.Modifier

/**
 *  Helper to exchange loggers set by lombok with mock logger
 *
 * allows to assert log action.
 *
 * Undos change after test to keep normal logging in other tests.
 *
 * code from this  <a href="https://stackoverflow.com/a/25031713/3573038">answer</a> answer
 */
class ReplaceSlf4jLogger extends ExternalResource {
  Field logField
  Logger logger
  Logger originalLogger

  ReplaceSlf4jLogger(Class logClass, Logger logger) {
    logField = logClass.getDeclaredField("log")
    this.logger = logger
  }

  @Override
  protected void before() throws Throwable {
    logField.accessible = true

    Field modifiersField = Field.getDeclaredField("modifiers")
    modifiersField.accessible = true
    modifiersField.setInt(logField, logField.getModifiers() & ~Modifier.FINAL)

    originalLogger = (Logger) logField.get(null)
    logField.set(null, logger)
  }

  @Override
  protected void after() {
    logField.set(null, originalLogger)
  }
}

I would like to test log calls, but still see the log message.

I am using the solution from this answer, it works for the assertion but I don't see the log because it is a mock call.

I came up with this solution, which does a the call with the logger of the groovy spec.

 1 * logger.warn(_ , _) >> {
   msg, ex -> log.warn(msg, ex)
 }

But I find it verbose, any idea how I could create a helper function for it. I am not very familiar with functional groovy and moving this code into a function is not working.

I also tried a Spy instead of a Mock but that gets me an error because the logger class is final.

  import ch.qos.logback.classic.Logger  

  private Logger logger = Spy(Logger.class)

>> org.spockframework.mock.CannotCreateMockException: Cannot create mock 
for class ch.qos.logback.classic.Logger because Java mocks cannot mock final classes. 
If the code under test is written in Groovy, use a Groovy mock.

Logger class at runtime

package ch.qos.logback.classic;

public final class Logger implements org.slf4j.Logger, LocationAwareLogger, AppenderAttachable<ILoggingEvent>, Serializable {

Thanks

Answer 1

Actually in your MCVE you expect the warn(_, _) method to be called with two parameters, but you are not logging like that in Clazz, so either you have to change Clazz to also log an exception or change the test to expect a method call with one parameter. I am doing the latter here.

As for your problem, the solution is to not use a mock but a spy. You need to tell Spock which exact class you want to spy on, though. This is because you cannot spy on an interface type, of course. I have chosen a SimpleLogger (change to whatever you use in your application).

package de.scrum_master.stackoverflow

import groovy.util.logging.Slf4j
import org.junit.Rule
import org.slf4j.impl.SimpleLogger
import spock.lang.Specification

@Slf4j
class LombokSlf4jLogTest extends Specification {
  SimpleLogger logger = Spy(constructorArgs: ["LombokSlf4jLogTest"])

  @Rule
  ReplaceSlf4jLogger replaceSlf4jLogger = new ReplaceSlf4jLogger(Clazz, logger)

  def "warning is logged"() {
    when: "when calling the method"
    new Clazz().method()

    then: "a warning is logged"
    1 * logger.warn(_)
  }
}

---

Update: For what it is worth, here is a version which also works with LogBack-Classic instead of Log4J-Simple on the classpath. Instead of directly spying on the final class, let's just spy on a Groovy @Delegate:

Please also note that I changed to *_ in the test so as to accommodate to warn calls with an arbitrary number of arguments.

package de.scrum_master.stackoverflow

import groovy.util.logging.Slf4j
import org.junit.Rule
import org.slf4j.Logger
import spock.lang.Specification

@Slf4j
class LombokSlf4jLogTest extends Specification {
  def logger = Spy(new LoggerDelegate(originalLogger: log))

  @Rule
  ReplaceSlf4jLogger replaceSlf4jLogger = new ReplaceSlf4jLogger(Clazz, logger)

  def "warning is logged"() {
    when: "when calling the method"
    new Clazz().method()

    then: "a warning is logged"
    1 * logger.warn(*_)
    true
  }

  static class LoggerDelegate {
    @Delegate Logger originalLogger
  }
}

---

Update 2020-01-23: I just found this one again and noticed that I forgot to explain why the @Delegate solution works: because a Groovy delegate automatically implements all interfaces which the class of the delegate instance also implements by default. In this case the logger field is declared as Logger which is an interface type. This is also why e.g. Log4J or Logback instances can be used based on the configuration. The trick of mocking or spying on a final class type not implementing an interface or used explicitly with its class name would not work in that case because the delegating class would not (and could not) be a subclass of the final class type and thus could not be injected instead of the delegate.

---

Update 2020-04-14: I did not mention before that if you don't want to spy on a real logger but simply use a dummy you can check interactions on, just use a regular Spock mock on the org.slf4j.Logger interface: def logger = Mock(Logger) That is actually the simplest solution and you don't clutter your test log with exception stack traces and other log output. I was so focused on helping the OP with his spy solution that I did not mention this before.

Answer 2

These is one more "creative" approach for this kind of issue I would like to share.

Instead of mocking the logger you can create an "artificial" appender, add it programmatically to the logger in the class under-test.

The appender will keep track of the logged messages and during the verification phase you will get those logged message and verify

You'll end up with something like this (pseudo code just to show the idea):

class MsgTrackingAppender implements Appender { // Appender of your logging system
   private List<LogEvent> events = new ArrayList<>();

   public void doAppend(LogEvent evt) {
       events.add(evt);
   }

   public List<LogEvent> getEvents() {
       return events;
   }
}

// now in test you can do:
class LogSpec extends Specification {

   def "test me"() {
     given:
       Clazz underTest = Clazz()
       MsgTrackingAppender appender = new MsgTrackingAppender()
       LogFactory.getLogger(Clazz.class).addAppender(appender)
     when:
       underTest.method()
     then:
       appender.events.size == 1
       appender.events[0].level == Level.WARN
       appender.events[0].message == ... // verify whatever you want on the messages       
   }
}

IMO this approach is easier to use than extensive mocking but its a matter of taste of course.