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://mcmap.net/q/766991/-unit-testing-of-a-class-with-staticloggerbinder">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

Whimsical

Share an MCVE, please. "I am doing something like the other guy, but it does not do what I expected" hardly qualifies as an answerable question. I like to see your Spock spec as well as the code under test in order to be able to reproduce and understand your problem. If this is asking too much, go solve your problem alone. – Nancee

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.

Nancee

I tried the spy approach but I use a final Logger class at runtime see the end of my question. So if I use another Logger class as a Spy in the test the output might differ. That's why I got the idea to build a helper function that asserts the log call and logs it again. – Whimsical

I used your code, there is no final Logback logger anywhere to be seen, only a Log4J logger. You only mention it in a small snippet unrelated to the MCVE. It seems the MCVE actually isn't really one. So unless you make the problem reproduceable for me, how am I supposed to help you? I dislike wasting my time. My solution works with your code! So if your code is different, your question is the problem, not my answer. P.S.: You edited your code after I answered. – Nancee

Another point: If the output would differ does not matter for your test. What does matter is that the logger method is called with the expected parameter(s), and this you can test with my approach. Besides, both LogBack Classic and Slf5J-Simple implement the same interface, thus they are drop-in replacements for each other. And your own solution also directly mocks the interface, it does not inject a LogBack-Classic instance into Clazz either. – Nancee

Update: See my second sample test if you want to know how to use a Spock Spy on a Groovy @Delegate instead of directly spying on a final class. I hope you are happy now. – Nancee

Thanks for your effort. That works for me and I am indeed happy! – Whimsical

Update 2: Please note my (very much belated) explanation of why the @Delegate solution works and under which circumstances it would not work. I want this answer to be as useful as possible to future readers. – Nancee

Great answer, thanks. Especially interested in the @Delegate part, nice one – Bandaranaike

Update 3: I also mentioned how to simply use a mock on the logger interface instead of a spy if you do not need the test to do any real logging but just want to check that the logger was called as expected. – Nancee

Would the same thing be possible creating a Spock extension instead of a JUnit rule? I'm a bit stuck on passing in the mocked logger. – Dunn

Hm, I do not remember the particulars of this question, I would have to re-read it and my whole answer in order to remember. Given the fact that rules are a JUnit4 thing and Spock2 is based on JUnit5 (even though for now there is a compatibility module which lets you use rules), maybe it would be more interesting to think about a Spock extension anyway. But please, write a new question, show an MCVE, as far as you got, and explain what exactly does not work. One of the Spock maintainers or me can take a look then, whoever is faster. – Nancee

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.

Patrol

I just noticed this answer because there was activity on mine. I like creative approaches, especially if they are clean. You basically build your own test double (technically what in Spock would be called a stub) and inject it as a dependency (or as a collaborator, pick a term) into the logger. While I still prefer to "mock out" dependencies as "flatly" as possible, yours goes one level deeper by using a real logger (which also requires the rest of the logging infrastructure), injecting your "diagnostic appender". Very nice indeed. – Nancee