Creating groovy @Log call protection annotations inside closures

Question

EDIT : GROOVY-6932 has been registered and is now closed - the problem is marked as fixed in Groovy v2.4.8.

I use the @ Slf4j annotation to add a log to my Groovy classes.

I like this because of the AST transformation, which wraps my logical calls inside the “enable” check, is documented here

What I found is that the guard clause does not work if the log method is called from a closure.

By running Groovy 2.2.0, this code only logs one message, but prints "called" twice.

@Grapes([ @Grab(group='org.slf4j', module='slf4j-api', version='1.7+'), @Grab(group='ch.qos.logback', module='logback-classic', version='1.+')]) import groovy.util.logging.Slf4j new TestCode().doSomethingThatLogs() @Slf4j class TestCode { void doSomethingThatLogs(){ log.info createLogString(1) log.trace createLogString(2) Closure c = { log.trace createLogString(3) } c() } String createLogString(int p){ println "called with $p" return "blah: $p" } } 

I tried adding the parameters "this", "owner" and "delegate" to the log statement, but the same result.

The context in which I found this was when I tried to register some nodes using XmlUtil.serialize when parsing XML using XmlSlurper.

I am working on a problem by wrapping a NodeChild object in a lightweight object using the toString () method, which calls the XmlUtil class. This will work fine, and the overhead of additional wrapper classes is not worth the trouble. I'm more interested in finding a simple way to solve this problem, so that I can return to not thinking about the cost of building log messages when they are not logged in any way.

The question I am asking is: is there a way for the security condition for the logging level to work correctly within the closures, instead of adding the "log.traceEnabled" call itself?

Answer 1

Just think it over. How do you know what log.traceEnabled will be on close? See Modified Example ...

 @Grapes([ @Grab(group='org.slf4j', module='slf4j-api', version='1.7+'), @Grab(group='ch.qos.logback', module='logback-classic', version='1.+')]) import groovy.util.logging.Slf4j import jline.internal.Log import org.slf4j.LoggerFactory; import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Logger; new TestCode().doSomethingThatLogs() @Slf4j class TestCode { void doSomethingThatLogs(){ log.info createLogString(1) log.trace createLogString(2) Closure c = { log.trace createLogString(3) } Logger root = (Logger)LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); root.setLevel(Level.TRACE); c() } String createLogString(int p){ println "called with $p" return "blah: $p" } } 

Now, at the moment the closure is log.traceEnabled is false, but when the closure is done, it has changed.

Output:

 called with 1 16:53:15.408 [main] INFO TestCode - blah: 1 called with 3 16:53:15.414 [main] TRACE TestCode - blah: 3 

Please note that the second TRACE is still not printed :-)