Grails® Mock Logging
May 24, 2018
In Grails® 3 applications, logging is handled by the Logback logging framework. Grails artifacts are configured with logging out of the box. The developer simply invokes log.info("log whatever") and it works. But how do we create unit tests that assert that logs occur with the appropriate level?
This blog will highlight some mock logging techniques and when to use them.
Default Grails Logging in Unit Tests
First let's get the obvious out of the way for clarity. If you are not concerned about testing how logs operate in your application, there is no reason to worry about mocking loggers in Grails apps.
Since the logger is already present in Grails controllers, services, and domain objects there is no need to mock the logger when running unit tests. When a unit test is run with Grails Testing Support, the logger will execute just as in does in production mode. In this scenario, we can say the logger as already "mocked" for the purpose of focusing on the Class Under Test. This is distinct from the scenario of actually verifying logging occurs, which we will dive into next.
Verify Logging with Tests
What if we want to assert that a certain log occurs with a particular log level? For example, let's say we want to test that that the method below prints friendly advice based on the age parameter.
package mock.logging
class AgeService {
void offerAgeAdvice(int age) {
if (age < 0) {
log.error ("You cannot be $age years old!")
} else if (age in 0..<30) {
log.info ("You are a young and vibrant :) Age $age")
log.info ("Live life to the fullest")
} else if (30 <= age) {
log.warn ("It's all downhill from here, sorry. Age $age")
}
}
}
In this scenario we need to mock the logger and capture the message passed in. Then we can assert that the message is correct and also assert the appropriate log level was used in each scenario. Conceptually, this is pretty easy. But in practice not so much.
Why Not Use Spock?
One would think that we should simply mock out the logger with def mockLogger = Mock(Logger), then set the service in the unit test with service.log = mockLogger. We could proceed to check the arguments passed in and also the number of times service.log is called with spock programming. However, in Grails apps we run into a few basic problems while trying to mock with native spock or even Groovy MockFor.
Logback is the default framework and the Logger is final. We cannot mock a final class. Furthermore, the injected logproperty in Grails artifacts is a read-only property and cannot be set. These two fundamental problems prohibit spock mocks from being effective in most mock logging situations in Grails apps.
Use Mockito to Verify Log Events
The Mockito Library can be used to verify logs take place. With Mockito, we can create a mock Appender class, attach it to the logger, and then use an ArgumentCaptor to capture the invocations sent to the logger.
build.gradle
dependencies {
...
testCompile "org.mockito:mockito-core:2.+"
}
Spock test with Mockito
void "verify logging with mockito appender"() {
when: "we attach a mocked appender to the logger"
Appender mockedAppender = Mockito.mock(Appender)
Logger logger = LoggerFactory.getLogger("mock.logging.AgeService")
logger.addAppender(mockedAppender)
service.offerAgeAdvice(22)
ArgumentCaptor<Appender> argumentCaptor = ArgumentCaptor.forClass(Appender)
Mockito.verify(mockedAppender,
Mockito.times(2)).doAppend(argumentCaptor.capture())
logger.detachAppender(mockedAppender)
then: "we capture the arguments and verify log statements occurred"
argumentCaptor.getAllValues().size() == 2
List<LoggingEvent> loggingEvents = argumentCaptor.getAllValues()
loggingEvents[0].getMessage() == "You are a young and vibrant :) Age 22"
loggingEvents[0].getLevel() == Level.INFO
loggingEvents[1].getMessage() == "Live life to the fullest"
loggingEvents[1].getLevel() == Level.INFO
}
Use Slf4j Test to Verify Log Events
Slf4j Test is a test implementation of Slf4j that stores log messages in memory and provides messages for retrieving them. This works nicely to substitute for the real implementation in the test environment of Grails apps.
In build.gradle, we first need to depend on the jar, and then exclude the real implementation from the test environment. It is quite simple to check the logging events.
build.gradle
dependencies {
...
testCompile 'uk.org.lidalia:slf4j-test:1.1.0'
}
configurations {
testCompile.exclude group: 'ch.qos.logback', module: 'logback-classic'
}
Spock test with Slf4j Test
void "verify logging with slf4j-test"() {
when:
TestLogger logger = TestLoggerFactory.getTestLogger("logging.AgeService")
service.offerAgeAdvice(-1)
ImmutableList<LoggingEvent> loggingEvents = logger.getLoggingEvents()
then:
loggingEvents.size() == 1
loggingEvents[0].message == "You cannot be -1 years old!"
loggingEvents[0].level == uk.org.lidalia.slf4jext.Level.ERROR
}
Use Spock Mocks With a Declared Logger
Spock mocks can be used on one particular case: with your own declared logger variable. If defined as non-final, you can use spock mocks to verify log calls. This approach is straightforward, but has the drawback that each class will have repeated code and does not rely on Grails conventions.
For example, use a LoggerFactory to define a logger in a class.
package mock.logging
import org.slf4j.Logger
import org.slf4j.LoggerFactory
/**
* Non grails groovy class with a declared Slf4j logging object
*/
class DeclaredSlf4jService {
private static Logger log = LoggerFactory.getLogger(DeclaredSlf4jService)
void logSomething() {
println "*********** log in the class ******" + log.dump()
log.info("Live life to the fullest")
}
Then a spock Specification with Mock() follows the normal spock conventions to verify invocations and parameters.
package mock.logging
import org.slf4j.Logger
import spock.lang.Specification
class DeclaredSlf4jServiceSpec extends Specification {
DeclaredSlf4jService declaredSlf4jService = new DeclaredSlf4jService()
def mockLogger = Mock(Logger)
def setup() {
declaredSlf4jService.log = mockLogger
}
def cleanup() {
}
void "test mock with spock on declared logger"() {
when:
declaredSlf4jService.logSomething()
then:
1 * mockLogger.info("Live life to the fullest")
}
}
Sample Code
Sample code of Grails mocking logging can be found here. I hope these examples can help you decide on the best approach for your project.