How Java logging frameworks determine caller class and method name

Apr 8, 2014

This post describes how java logging frameworks (Log4j, for example) know a point (concrete class and method name), where logging statement has been invoked.

I decided to write this post, because quite often I communicate with developers, who do not understant what is the cost of writing caller information to logs, and why such high cost is imposed.

Brief Log4J configuration and usage overview

Logger is identified by its name (a.k.a. category). Common myth here, is that logger is somehow connected with the class it is declared in. The myth is based on the signature of the factory method:

private static final Logger log = LogManager.getLogger(MyService.class);

but that’s just a shortcut for

LogManager.getLogger(MyService.class.getName());

Category vs Caller class name

It is important to understand the difference between logger category (placeholder %c in PatternLayout) and caller class name (%C).

Consider the following example

package com.my.company.name;
public class MyService {

  private static final Logger log1 = LogManager.getLogger(MyService.class);
  private static final Logger log2 = LogManager.getLogger("blah-blah");

  public void f() {
    log1.debug("I'm log1");
    log2.debug("I'm log2");
  }
}

When call to f() is performed while logger is configured with pattern %c - %m%n, log will contain

com.my.company.name.MyService - I'm log1
blah-blah - I'm log2

On the other hand, if pattern is %C - %m%n, we’ll get

com.my.company.name.MyService - I'm log1
com.my.company.name.MyService - I'm log2

Despite of being named blah-blah, the second logger somehow determined its caller class name.

How does it work?

Before JVM enters any method, it records the point from which this method is invoked to be able to return to that same point later, after the method returns. Let’s look at simple example

public class Example {
  public static void main(String[] args) { a(); }
  static void a() { getCallerInfo(); }
  static void getCallerInfo() { b(); }
  static void b() { throw new RuntimeException(); }
}

Method b() throws an exception. Exception reaches the very top without being caught and its stacktrace gets printed to System.err:

Exception in thread "main" java.lang.RuntimeException
 at Example.b(Example.java:7)
 at Example.getCallerInfo(Example.java:6)
 at Example.a(Example.java:5)
 at Example.main(Example.java:4)

Having that stacktrace it is easy to say, that method getCallerInfo() has been called from method a(). So if we could get that stacktrace in runtime somehow and analyze it, we could find an invocation point for any method in our application.

Obtaining stacktrace

There are few ways to get stacktrace in Java: Thread.getStackTrace() and Throwable.getStackTrace(). Both methods return array of StackTraceElement.

Throwable.getStackTrace()

Usage is as simple as

new Throwable().getStackTrace();

Stacktrace gets filled in when Throwable is created, so no need to throw it. Moreover, it is possible to reuse the same Throwable instance calling fillInStacktrace() to refresh stacktrace when needed (of course, keeping in mind possible race conditions if shared across threads). Under the hood native method Throwable.fillInStackTrace(int dummy) is invoked eventually.

Thread.getStackTrace()

Usage is

Thread.currentThread().getStackTrace();

Although a bit cleaner, this method does not give other benefits and is a bit slower (it has to check, whether stack trace is obtained for current thread of for some other thread, doing necessary security checks if required). And in the end stacktrace is obtained from new Exception instance in a way described above.

Parsing stacktrace

So we got array of StackTraceElement. We need to iterate through that array and find such element whichs declaring class and method name properties satisfy some criteria:

"debug".equals(methodName) & "my.company.Logger".equals(declaringClass)

Here is very simple straightforward implementation of a logger, which knows everything about its caller.

public class Logger {

  /**
   * Log message to stderr along with the caller class and method name.
   * @param msg message to log
   */
  public final void log(String msg) {
    StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    // Index of StackTraceElement in stacktrace, where our logger appears.
    int i = getSelfElementIndex(stackTrace, this.getClass());
    // Caller is the next item down the stack.
    StackTraceElement caller = stackTrace[i + 1];
    System.err.println(caller.getClassName() + "." + caller.getMethodName() + ": "
       + msg);
  }

  private int getSelfElementIndex(StackTraceElement[] stackTrace) {
    for (int i = 0; i < stackTrace.length; i++) {
      StackTraceElement el = stackTrace[i];
      // We don't need to check method name, our logger has only one method.
      if (el.getClassName().equals(this.getClass().getName())) {
        return i;
      }
    }
    throw new IllegalStateException("Logger doesn't appear in stacktrace");
  }
}

What about log4j

Of course, it’s a bit more complicated than that. Good points to start investigation are

  • org.apache.log4j.spi.LocationInfo
  • org.apache.log4j.helpers.PatternParser.LocationPatternConverter