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

Question

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 1

The problem occurs when a GString is logged (any normal String logs the correct line number). 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)
    }
}