Michal Z m u d a Michal Z m u d a - 3 months ago 24
Groovy Question

Why Logback/Slf4j logs wrong file and line numbers in Groovy?

I have noticed that sometimes Logback/Slf4j logs wrong file and line numbers in Groovy.

I have a lot of bad file/line number logs in my Grails application (more than 50% of all logs)

Is there any workaround?

Simplest example:

logback.groovy

appender("STDOUT", ConsoleAppender) {
encoder(PatternLayoutEncoder) {
pattern = '%d{HH:mm:ss.SSS} [%-5level] %msg \\(%file:%line\\)%n'
}
}

root(DEBUG, ["STDOUT"])


Test.groovy

@Slf4j
class Test {
static void main(String[] args) {
log.info("${'Wrong file and line number!'}")
}
}


Output

23:24:23.894 [INFO ] 0 Wrong file and line number! (NativeMethodAccessorImpl.java:-2)


Example of my grails log output with problem

10:16:44.881 [DEBUG] [org.grails.plugin.resource.ResourceProcessor] -------------------------------------------------- (null:-1)

Answer

The problem occurs when a GString is logged and any normal String has the correct line number logged. I have no clue why it works like this but I have found two workarounds: Either convert GString to String by calling the toString() method (ugly) or use template format with parameters

import groovy.util.logging.Slf4j;

@Slf4j
class Test {
    static void main(String[] args) {
        def x = 1
        log.info("Does not work: ${x}")
        log.info("Works ${x}".toString())
        log.info("Works {}", x)
    }
}
Comments