0

I'm developing an app in Groovy.

I'm using the helpful "AST" tag @Slf4j - which adds a new property to your class, log. I have configured this to be a ch.qos.logback.classic.Logger.

Now I want to test (using Spock) that an error level message is logged. NB the start method calls the loop method. This is inspired by this question:

import org.slf4j.Logger
...

ConsoleHandler ch = Spy( ConsoleHandler )
ch.setMaxLoopCount 3
ch.loop() >> { throw new Throwable() }
ch.log = Mock( Logger )

when:
ch.start()

then:
1 * ch.log.error( 'dummy' )

Fails...

groovy.lang.MissingMethodException: No signature of method: core.ConsoleHandler.setLog() is applicable for argument types: (ch.qos.logback.classic.Logger) values: [Logger[null]] Possible solutions: stop(), setMode(java.lang.Object), getMode(), start(javafx.stage.Stage), start(javafx.stage.Stage), getAt(java.lang.String)

Before you ask, I also tried:

ConsoleHandler ch = Spy( ConsoleHandler )
ch.setMaxLoopCount 3
ch.loop() >> { throw new Throwable() }
Logger mockLogger = Mock( Logger )
ch.getLog() >> mockLogger

when:
ch.start()

then:
1 * mockLogger.error( 'dummy' )

... this gave "too few invocations", although the string "dummy" was indeed logged to error. My suspicion at this point is just that log can't be mocked because it is a property added through Groovy AST magic.

Can anyone think of a solution? Other than, maybe, an inelegant wrapper class which forwards log messages on to the AST log?

Szymon Stepniak
  • 40,216
  • 10
  • 104
  • 131
mike rodent
  • 14,126
  • 11
  • 103
  • 157

2 Answers2

1

You cannot override log field, because it's a final static field. You see this

groovy.lang.MissingMethodException: No signature of method: core.ConsoleHandler.setLog() applicable for argument types: (ch.qos.logback.classic.Logger) (...)

exception, because final fields don't have any setter method. If it was not a final field you could try overriding it with:

ch.@log = Mock(Logger)

@ in this case means that you want to access object field directly (Groovy compiles ch.log to ch.getLog() when accessing value and ch.setLog() when modifying field).

In general, you shouldn't test if logger logged any message inside the feature you are testing. Basically because it is out of scope of your current unit under test and if it comes to what your method returns - it doesn't matter if anything was logged or not. Also you don't even know if ERROR level is enabled or not - it means that your test won't recognize if anything was actually logged to an appender or not. And secondly, at some point of time you can add another log.error() to the method you test - it does not change anything to what your class or method provides, but the unit test starts failing, because you assumed that there is a single invocation of log.error().

If you are not convinced by those arguments, you can apply a hack to your test. You can't mock ch.log field, but if you take a look what class it instantiates (org.slf4j.impl.SimpleLogger) and what log.error() calls in the end, you can find out that it gets PrintStream object from:

CONFIG_PARAMS.outputChoice.getTargetPrintStream()

And because CONFIG_PARAMS.outputChoice is not a final field, you can replace it with a mock. You still can't check if log.error() was invoked, however you can check if mocked PrintStream invoked .println(String str) method n-number of times. This is very ugly solution, because it relies on internal implementation details of a org.slf4j.impl.SimpleLogger class. I would call such workaround as an asking yourself for a problems, because you couple your test tightly to current org.slf4j.impl.SimpleLogger implementation - it's pretty easy to imagine that a few months later you update Slf4j to a version that changes implementation of log.error() and your test starts failing with no strategic reason. Here is what this dirty workaround looks like:

import groovy.util.logging.Slf4j
import org.slf4j.impl.OutputChoice
import spock.lang.Specification

class SpyMethodArgsExampleSpec extends Specification {

    def "testing logging activity, but why?"() {
        given:
        ConsoleHandler ch = Spy(ConsoleHandler)

        PrintStream printStream = Mock(PrintStream)
        ch.log.CONFIG_PARAMS.outputChoice = Mock(OutputChoice)
        ch.log.CONFIG_PARAMS.outputChoice.getTargetPrintStream() >> printStream

        when:
        ch.run()

        then:
        1 * printStream.println(_ as String)
    }

    @Slf4j
    static class ConsoleHandler {
        void run() {
            log.error("test")
        }
    }
}

However I hope you won't go that way.

Update: making logging/reporting an important part of the feature we are implementing

Assuming that logging/reporting part is crucial to your class, it's worth rethinking your class design in this case. Defining class dependencies as a constructor parameters is a good practice - you explicitly express class dependencies at initialization level. Using @Slf4j is very convenient way to add a static final logger, but in this case it's an implementation level detail and it's not visible from public client perspective. That's why testing such internal details is very tricky.

However, if logging is important to your class and you want to test interactions between class under test and its dependencies, there is nothing wrong in skipping @Slf4j annotation and providing logger as a constructor parameter:

class ConsoleHandler {
    private final Logger logger

    ConsoleHandler(Logger logger) {
        this.logger = logger
    }
}

Of course it has downsides as well - you need to pass it anytime you create an instance of ConsoleHandler class. But it makes it fully testable - in your test you simply mock Logger instance and you are ready to go. But it makes sense only if testing those interactions makes sense from business perspective and those invocations are mandatory to fulfill the contract with the class you are testing. Otherwise it doesn't make much sense.

Szymon Stepniak
  • 40,216
  • 10
  • 104
  • 131
  • Thanks... I won't! So if I understand you correctly, all logging activity is basically to be considered "outside the scope of testing". I'm slighting trying to get my head around this because correct reporting/logging (particularly on things that go wrong) is surely a non-trivial part of an app. Re the possibility of other "log.error" messages interfering: I was planning to address that by (hopefully) capturing the logger error-level output and testing it against a regex. But now I'm not sure what to think: indirection via a (testable) "logError" method seems rubbish too... ! (sigh!) – mike rodent Feb 27 '18 at 18:38
  • 1
    @mikerodent It depends. If logging at error/info/debug level is only an implementation detail and does not affect business logic your class provides - it doesn't make sense to test those interactions. But on the other hand - if logging is a part of requirement you can "contract" `ConsoleHandler` with `Logger` by expecting `Logger` as a constructor parameter - all clients know in these case, that using `ConsoleHandler` requires a valid logger. And your test may cover mandatory interactions in these case. You just have to expose this contract instead of keeping it as an implementation detail – Szymon Stepniak Feb 27 '18 at 18:53
  • Ah, right... I understand. Thanks again, this is a really valuable explanation. Another thing that I get constantly confused about is that the way I'm developing using TDD, I don't really write any app code until a test is failing... often a new test. So it may not only be "business logic" which my tests cover... they hopefully cover... everything. If I wasn't proceeding in this way, would it really be TDD? I don't really expect an answer... I'm just trying to puzzle it out... :) – mike rodent Feb 27 '18 at 19:07
  • @mikerodent Absolutely. TDD is not dogmatic about what unit you should test - is it a class, a method, or something else. Personally - I like to test use cases, scenarios that reflect business processes in the application. Sometimes it means I write a test in scope of a single class, sometimes I test the whole package because it encapsulates the whole business process I want to design with TDD. In general - do what works best for you and the project. – Szymon Stepniak Feb 28 '18 at 05:50
0

Szymon Stepniak has come up with a very ingenious solution, but recommended me not to use it... for all the right reasons explained in his last paragraph (and discussion with me).

If you think that it is an acceptable thing to wish to monitor logging using this @Slf4j AST Logger directly it appears this is not possible without using something contrived, fragile and (in his words) ugly. Any workaround seems to mean you have to use some other mockable object and delegate from it.

I just happened to find a useful class org.slf4j.helpers.SubstituteLogger. It kind of defeats the object somewhat, in the sense that it can be argued that you might as well create a Logger in the normal way... but it's one POSSIBLE idea for wrapping the AST log so you can check on some of the things it's being asked to do. NB this AST log offers more than just logging as per Java: you can also do execution of closures dependent on log level (see Groovy in Action 2nd Ed, p.252 NB looked for an online link without success: if there is one, please edit...)

In the app class:

Console Handler {
    SubstituteLogger substLog

    ConsoleHandler(){
        substLog = new SubstituteLogger( 'substLog', new ArrayDeque() /* for example */, true )
        substLog.delegate = log
    }

    ...

        log.info( "something banal which you don't want to test..." )
    ... 

    }catch( Exception e ){
        substLog.error( 'oops', e )
    }

test method:

    ConsoleHandler ch = Spy( ConsoleHandler )
    ch.loop() >> { throw new Throwable() }
    Logger mockLogger = Mock( SubstituteLogger )
    ch.substLog = mockLogger

    when:
    ch.start()

    then:
    1 * mockLogger.error( _, _ )
mike rodent
  • 14,126
  • 11
  • 103
  • 157