1

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.

mike rodent
  • 14,126
  • 11
  • 103
  • 157
  • the problem appears because groovy makes dynamic calls by default. for test - try to annotate with @CompileStatic just one method and it will print correct method name and line number. – daggett Dec 27 '19 at 04:31
  • @daggett Thanks very much for clearing up this mystery. I don't know enough to understand why "dynamic calls" should lead to this strange phenomenon, and specifically for this particular module: beyond my pay grade. – mike rodent Dec 27 '19 at 08:14
  • groovy searches all the methods in runtime rather then during compile-time. and calls them indirectly - for example through reflection [Method.invoke(...)](https://docs.oracle.com/javase/8/docs/api/java/lang/reflect/Method.html#invoke-java.lang.Object-java.lang.Object...-) – daggett Dec 27 '19 at 13:26
  • Yep, understand that: Groovy is obviously a dynamic language ... I still don't understand at all why dynamic method-calling could lead to such malfunctioning, particularly intermittent malfunctioning, of a module like logback: I'm surmising that somehow stack frame information gets stripped away... sometimes. I may try looking into it but don't have much expectation that I'll understand (let alone find a solution). – mike rodent Dec 27 '19 at 15:39
  • Linking to https://stackoverflow.com/questions/48221240/logback-line-number-is-not-showing-up-in-logs – Paul Verest Mar 18 '21 at 08:44

1 Answers1

3

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
mike rodent
  • 14,126
  • 11
  • 103
  • 157
daggett
  • 26,404
  • 3
  • 40
  • 56
  • Thanks a lot! This looks amazing. I'm going to see how to switch from an .xml file to a .groovy one for the config. Since I started using Groovy I've been aware of the incredible stack traces you get. `StackTraceUtils` has a `sanitize` and even `deepSanitize` methods to try and address this. No doubt your solution comes at a cost (time) but... wow! (NB I wonder whether Ceki, the author of logback, might be able to enlist these `sanitize` methods to make things functional in a Groovy context) – mike rodent Dec 27 '19 at 18:44
  • I've tested this quite a bit: it works sometimes but doesn't (so far) solve the problem. From my first experiments, it still often prints "invoke" and "-1", particularly when the log message contains interpolated Groovy placeholders (or whatever you call them: ${var}). Also it sometimes doesn't print the method properly: "core.MiscSpec.$spock_feature_1_2:38": line 38, yes, but that feature also has a name. Could it be that yet more packages need to be added to the framework packages? – mike rodent Dec 28 '19 at 12:41
  • with `core.MiscSpec.$spock_feature_1_2` there is nothing to do - because after compilation that could be a real class/method name... to detect additional framework packages you could add to the pattern `%class` placeholder and when you see incorrect classname - just add its package to the list. – daggett Dec 28 '19 at 23:48
  • +1 Madam/Sir, I salute your genius! I included `%class` and that revealed another package to include: "jdk.internal.reflect"... now I'm really getting results. I'm going to suggest an edit to your answer for the sake of future readers of your answer. – mike rodent Dec 29 '19 at 10:52