Tuesday, February 10, 2015

Grails fails to log an Exception mock

I recently worked on a small fix for elasticsearch-grails-plugin. The fix was basically to reduce the severity of an error. It included throwing a custom exception and logging it when it is caught.
When I came to write some spock tests, I wanted to make sure the exception is thrown for the expected cases. For this goal I decided to mock the exception's constructor - to intercept this interaction and make sure it happens as expected. I used a global spy on the exception.

given:
...
GroovySpy(MappingException, global: true)

when:
results = unmarshaller.buildResults(searchHits)

then:
1 * new MappingException('Property Color.red found in index, but is not defined as searchable.')
0 * new MappingException(_)
...


When I first ran this test it failed with the following exception:

ERROR unmarshall.DomainClassUnmarshaller - Error unmarshalling property 'color' of Class Circle with id 1
Message: No signature of method: org.grails.plugins.elasticsearch.exception.MappingException.getName() is applicable for argument types: () values: []
Possible solutions: getCause(), getAt(java.lang.String), getClass(), getMessage()
Line  | Method
-> 56 | unwrap in org.codehaus.groovy.runtime.ScriptBytecodeAdapter
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - 
| 50  | getProperty in org.codehaus.groovy.runtime.callsite.ClassMetaClassGetPropertySite
| 227 | callGetProperty . . . . . in org.codehaus.groovy.runtime.callsite.AbstractCallSite
| 42  | prettyPrint in org.codehaus.groovy.grails.exceptions.DefaultStackTracePrinter
| 94  | buildMessage . . . . . . . in org.codehaus.groovy.grails.plugins.log4j.appenders.GrailsConsoleAppender
| 56  | append in ''
| 251 | doAppend . . . . . . . . . in org.apache.log4j.AppenderSkeleton
| 66  | appendLoopOnAppenders in org.apache.log4j.helpers.AppenderAttachableImpl
| 206 | callAppenders . . . . . . in org.apache.log4j.Category
| 391 | forcedLog in ''
| 856 | log . . . . . . . . . . . in ''
| 192 | logMessage in org.slf4j.impl.GrailsLog4jLoggerAdapter
| 95  | debug . . . . . . . . . . in ''
| -2  | invoke0 in sun.reflect.NativeMethodAccessorImpl
| 57  | invoke . . . . . . . . . . in ''
| 43  | invoke in sun.reflect.DelegatingMethodAccessorImpl
| 606 | invoke . . . . . . . . . . in java.lang.reflect.Method
| 210 | invoke in org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite$PojoCachedMethodSiteNoUnwrap
| 53  | call . . . . . . . . . . . in org.codehaus.groovy.runtime.callsite.PojoMetaMethodSite
| 45  | defaultCall in org.codehaus.groovy.runtime.callsite.CallSiteArray
| 108 | call . . . . . . . . . . . in org.codehaus.groovy.runtime.callsite.AbstractCallSite
| 120 | call in ''
| 283 | unmarshallDomain . . . . . in org.grails.plugins.elasticsearch.conversion.unmarshall.DomainClassUnmarshaller

This is line 42 in DefaultStackTracePrinter:

if (e.getClass().name.contains('NestedServletException')) {

As you can, see this is where the 'getName()' method is called on the exception's class. This is where it fails. It happens when the exception is being logged (line 95 in GrailsLog4jLoggerAdapter).

After struggling with this issue for some time, I decided to mock the logger. The problem here is that the logger instance in the class under test is declared as static final. Modifying the class implementation for the sake of this test was not an option. The solution was a hack - use reflection to inject the mock logger. Since the logger is static in the class, I needed make sure to reset to the original logger in the end of the test. For better readability I decided to use a method which takes a closure and wrap it with try-finally.

Calling the method under test is now done safely and cleanly with a mock logger:

when:
withMockLogger {
   results = unmarshaller.buildResults(searchHits)
}


And 'withMockLogger' is the real hack:

private void withMockLogger(Closure closure) {
   def logField = DomainClassUnmarshaller.class.getDeclaredField('LOG')
   logField.setAccessible(true)
   Field modifiersField = Field.class.getDeclaredField("modifiers");
   modifiersField.setAccessible(true);
   modifiersField.setInt(logField, logField.getModifiers() & ~Modifier.FINAL);

   Logger origLog = logField.get(null)
   Logger mockLog = Mock(Logger) {
      debug(_ as String) >> { String s -> if (origLog.debugEnabled) println("DEBUG: $s") }
      debug(_ as String, _ as Throwable) >> { String s, Throwable t -> if (origLog.debugEnabled) { println("DEBUG: $s"); t.printStackTrace(System.out) } }
      error(_ as String) >> { String s -> System.err.println("ERROR: $s") }
      error(_ as String, _ as Throwable) >> { String s, Throwable t -> System.err.println("ERROR: $s"); t.printStackTrace() }
   }
   try {
      logField.set(null, mockLog)
      closure.call()
   } finally {
      logField.set(null, origLog)
   }
}