Unit testing of a class with StaticLoggerBinder

Question

I do have a simple class like this:

package com.example.howtomocktest

import groovy.util.logging.Slf4j
import java.nio.channels.NotYetBoundException

@Slf4j
class ErrorLogger {
    static void handleExceptions(Closure closure) {
        try {
            closure()
        }catch (UnsupportedOperationException|NotYetBoundException ex) {
            log.error ex.message
        } catch (Exception ex) {
            log.error 'Processing exception {}', ex
        }
    }
}

And I would like to write a test for it, here is a skeleton:

package com.example.howtomocktest

import org.slf4j.Logger
import spock.lang.Specification
import java.nio.channels.NotYetBoundException
import static com.example.howtomocktest.ErrorLogger.handleExceptions

class ErrorLoggerSpec extends Specification {

   private static final UNSUPPORTED_EXCEPTION = { throw UnsupportedOperationException }
   private static final NOT_YET_BOUND = { throw NotYetBoundException }
   private static final STANDARD_EXCEPTION = { throw Exception }
   private Logger logger = Mock(Logger.class)
   def setup() {

   }

   def "Message logged when UnsupportedOperationException is thrown"() {
      when:
      handleExceptions {UNSUPPORTED_EXCEPTION}

      then:
      notThrown(UnsupportedOperationException)
      1 * logger.error(_ as String) // doesn't work
   }

   def "Message logged when NotYetBoundException is thrown"() {
      when:
      handleExceptions {NOT_YET_BOUND}

      then:
      notThrown(NotYetBoundException)
      1 * logger.error(_ as String) // doesn't work
   }

   def "Message about processing exception is logged when standard Exception is thrown"() {
      when:
      handleExceptions {STANDARD_EXCEPTION}

      then:
      notThrown(STANDARD_EXCEPTION)
      1 * logger.error(_ as String) // doesn't work
   }
}

The logger in ErrorLogger class is provided by StaticLoggerBinder, so my question is - how do I make it work so that those checks "1 * logger.error(_ as String)" would work? I can't find a proper way of mocking that logger inside of ErrorLogger class. I have thought about reflection and somehow accessing it, furthermore there was an idea with mockito injection (but how to do that if reference to an object is not even present in that class because of that Slf4j annotation!) Thanks in advance for all your feedback and advices.

EDIT: Here is an output of a test, even 1*logger.error(_) doesn't work.

Too few invocations for:

1*logger.error()   (0 invocations)

Unmatched invocations (ordered by similarity):

Lyon

Have you tried with just 1*logger.error(_)? It would also be helpful if you add the output to these tests. – Sparrowgrass

I added invocation. Unfortunately, 1*logger.error(_) doesn't work as well. – Lyon

An alternative for some use cases (likely the sample above) would be to use docs.groovy-lang.org/next/html/gapi/groovy/lang/… – Syst

Answer 1

What you would need to do is to replace the log field generated by the @Slf4j AST transformation with your mock.

However, this is not so easy to achieve, since the generated code is not really test-friendly.

A quick look at the generated code reveals that it corresponds to something like this:

class ErrorLogger {
    private final static transient org.slf4j.Logger log =
            org.slf4j.LoggerFactory.getLogger(ErrorLogger)
}

Since the log field is declared as private final it is not so easy to replace the value with your mock. It actually boils down to the exact same problem as described here. In addition, usages of this field is wrapped in isEnabled() methods, so for instance every time you invoke log.error(msg) it is replaced with:

if (log.isErrorEnabled()) {
    log.error(msg)
}

So, how to solve this? I would suggest that you register an issue at the groovy issue tracker, where you ask for a more test-friendly implementation of the AST transformation. However, this won't help you much right now.

There are a couple of work-around solutions to this that you might consider.

1. Set the new field value in your test using the "awful hack" described in the stack overflow question mentioned above. I.e. make the field accessible using reflection and set the value. Remember to reset the value to the original during cleanup.
2. Add a getLog() method to your ErrorLogger class and use that method for access instead of direct field access. Then you may manipulate the metaClass to override the getLog() implementation. The problem with this approach is that you would have to modify the production code and add a getter, which kind of defies the purpose of using @Slf4j in the first place.

I'd also like to point out that there are several problems with your ErrorLoggerSpec class. These are hidden by the problems you've already encountered, so you would probably figure these out by yourself when they manifested themselves.

Even though it is a hack, I'll only provide code example for the first suggestion, since the second suggestion modifies the production code.

To isolate the hack, enable simple reuse and avoid forgetting to reset the value, I wrote it up as a JUnit rule (which can also be used in Spock).

import org.junit.rules.ExternalResource
import org.slf4j.Logger
import java.lang.reflect.Field
import java.lang.reflect.Modifier

public 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)
    }

}

And here is the spec, after fixing all the small bugs and adding this rule. Changes are commented in the code:

import org.junit.Rule
import org.slf4j.Logger
import spock.lang.Specification
import java.nio.channels.NotYetBoundException
import static ErrorLogger.handleExceptions

class ErrorLoggerSpec extends Specification {

    // NOTE: These three closures are changed to actually throw new instances of the exceptions
    private static final UNSUPPORTED_EXCEPTION = { throw new UnsupportedOperationException() }
    private static final NOT_YET_BOUND = { throw new NotYetBoundException() }
    private static final STANDARD_EXCEPTION = { throw new Exception() }

    private Logger logger = Mock(Logger.class)

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

    def "Message logged when UnsupportedOperationException is thrown"() {
        when:
        handleExceptions UNSUPPORTED_EXCEPTION  // Changed: used to be a closure within a closure!
        then:
        notThrown(UnsupportedOperationException)
        1 * logger.isErrorEnabled() >> true     // this call is added by the AST transformation
        1 * logger.error(null)                  // no message is specified, results in a null message: _ as String does not match null
    }

    def "Message logged when NotYetBoundException is thrown"() {
        when:
        handleExceptions NOT_YET_BOUND          // Changed: used to be a closure within a closure!
        then:
        notThrown(NotYetBoundException)
        1 * logger.isErrorEnabled() >> true     // this call is added by the AST transformation
        1 * logger.error(null)                  // no message is specified, results in a null message: _ as String does not match null
    }

    def "Message about processing exception is logged when standard Exception is thrown"() {
        when:
        handleExceptions STANDARD_EXCEPTION     // Changed: used to be a closure within a closure!
        then:
        notThrown(Exception)                    // Changed: you added the closure field instead of the class here
        //1 * logger.isErrorEnabled() >> true   // this call is NOT added by the AST transformation -- perhaps a bug?
        1 * logger.error(_ as String, _ as Exception) // in this case, both a message and the exception is specified
    }
}

Paw

@Opal Thanks! It was both fun and interesting to dig into this. :) – Paw

Thanks a lot for great answer! I knew there were some bugs in my code as all this was a dummy,fake code that shows a problem that I encountered :) – Lyon

@MateuszChrzaszcz Yeah, I figured the code was created to present the problem. Since I had to fix the bugs in order to test the solution anyway, I chose to include the fixed version of the Spec. :) – Paw

@Paw this is an excellent answer and will solve the problem for lots of people. If you don't mind, I'll suggest that this hack becomes part of the Grails 3.3.x testing framework, and will make a PR, as it prevents lots of test-code breaking. – Sledge

Awesome! This still works in Grails 4 :) – Koala

Answer 2

If you are using Spring, you have acces to OutputCaptureRule

@Rule
OutputCaptureRule outputCaptureRule = new OutputCaptureRule()

def test(){
outputCaptureRule.getAll().contains("<your test output>")
}

Dingle

This is exactly what I needed. Thank you! – Mayhew