logback doesn't print method or line number

Question

This is in a Gradle project using Groovy for the app code as well as test code. But I'm using a logback.xml file for configuration.

One factor here that may be significant is that I am using the Groovy @Slf4j annotation to provide a logger.

The %method and %line conversion words usually get printed out as "invoke" and "-1" respectively (although sometimes "invoke0" with "-2").

Interestingly, it does sometimes print the method and number: for example when it's an ERROR level log with an Exception parameter:

log.error( 'indexSearcher.indexReader.close() threw Exception', e )

... I presume that's something to do with the e object carrying with it "location" data which logback can then exploit. But just occasionally an INFO level message gets printed with the method and line number: it's quite puzzling.

I've seen people having problems with an async appender, but my appender is ROLLING_FILE (RollingFileAppender). This is not an extension of an async appender.

I've tried other remedies documented in other SO questions (e.g. here): I've added these lines to my appender:

<includeCallerData>true</includeCallerData>
<param name="locationInfo" value="true" />

... did not solve the problem.

Someone somewhere said that it was necessary to ensure debug data was switched on at some point. In a Groovy context I'm not sure how I might try that idea.

Answer 1

logback.groovy

appender("STDOUT", ConsoleAppender) {
  encoder(PatternLayoutEncoder) {
    pattern = "%d{HH:mm:ss.SSS} [%thread] %-5level {%logger} - %class.%method:%line - %msg%n"
  }
}
root(DEBUG, ["STDOUT"])

X.groovy

@GrabConfig(systemClassLoader=true)
@GrabResolver(name='maven2',root='http://repo1.maven.org/maven2/')
@Grab(group='ch.qos.logback', module='logback-classic', version='1.2.3')
@Grab(group='org.slf4j', module='slf4j-api', version='1.7.30')

import groovy.util.logging.Slf4j

@Slf4j
class A {
    def f() {
        log.info 'msg-info-2'       //line 11
        log.with{
            info  'msg-info-1'      //line 13
            //new Exception("test").printStackTrace(System.out)
        }
    }
}

def a = new A()
a.f()

The command groovy X.groovy prints:

12:24:43.134 [main] INFO  {A} - A.f:11 - msg-info-1
12:24:43.139 [main] INFO  {A} - sun.reflect.NativeMethodAccessorImpl.invoke0:-2 - msg-info-2

---

why

in logback there is a class CallerData with method extract that extracts caller data information as an array based on a Throwable parameter and returns an array of StackTraceElement. It tries to cleenup the stacktrace, however for groovy it could be really complex.

For example if you uncomment the line new Exception("test").printStackTrace(System.out)

You'll see stacktrace like this:

java.lang.Exception: test
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    ... + 11 elements
    at A$_f_closure1.doCall(X.groovy:14)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    ... + 15 elements
    at A.f(X.groovy:12)
    ... + 20 elements

CallerData tries to skip the technical groovy elements from stacktrace but fails to detect the right one.

---

solution

It's possible to modify the Framework Packages for the logback context.

I don't know how to do that from logback.xml, but I found how to do it using logback.groovy

logback.groovy (modified)

maybe for your case you have to add another framework (ignored) packages...

context.getFrameworkPackages().addAll([
    "sun.reflect", 
    "java.lang.reflect", 
    "org.codehaus.groovy", 
    "groovy.lang.MetaMethod",
    "jdk.internal.reflect"
    ])

appender("STDOUT", ConsoleAppender) {
  encoder(PatternLayoutEncoder) {
    pattern = "%d{HH:mm:ss.SSS} [%thread] %-5level {%logger} - %class.%method:%line - %msg%n"
  }
}
root(DEBUG, ["STDOUT"])

with this configuration the code above prints lines correctly:

13:12:14.410 [main] INFO  {A} - A.f:11 - msg-info-2
13:12:14.416 [main] INFO  {A} - A$_f_closure1.doCall:13 - msg-info-1