Application Logging in Java: Tracing 3rd Party Code

11 Jun 2019 • logging

TL;DR: Tracing is a well known part of SLF4J, and tracing code in logs can be very useful in debugging. However, not all code is written with tracing in mind. To solve this, you can use Byte Buddy to instrument 3rd party code with tracing, and add it at runtime.

This is part of the series of blog posts:

Overview

Rather than defining tracing, let's give a demonstration. If you wrap your code in this:

public class Foo {
   private final Logger = LoggerFactory.getLogger(getClass());

   public void doStuff() {
       if (logger.isTraceEnabled()) {
           logger.trace("doStuff: enter");
       }
       System.out.println("hello world!");
       if (logger.isTraceEnabled()) {
           logger.trace("doStuff: exit");
       }
   }
}

Then you have tracing. You can then turn up the logging to TRACE and be able to see every time that method is called.

Tracing is wildly used for debugging and diagnostic logging. Diomidis Spinellis has a book, Effective Debugging, that discusses tracing and logging statements extensively and has also written about the advantages of diagnostic logging statements.

Still, there are a couple of objections that are raised when it comes to tracing statements.

  • Some people don't like "busy" nature of trace statements in every method.
  • Tracing only occurs when you've explicitly added those statements to a method.
  • If you don't own the code, you can't add tracing to it.

This post is about how to address these concerns.

XLogger

One solution to the "busy" tracing is to use XLogger. This is a class provided in the slf4j-ext module, which provides extensions over SLF4J.

In particular, the XLogger makes use of entry and exit, which use the Marker API under the hood. Not using the Marker API was the primary objection to adding the TRACE level, so this provides the facility out of the box, and is, I think, the SLF4J "response" to the demand for tracing:

The two most used methods are the entry() and exit() methods. entry() should be placed at the beginning of methods, except perhaps for simple getters and setters. entry() can be called passing from 0 to 4 parameters. Typically these will be parameters passed to the method. The entry() method logs with a level of TRACE and uses a Marker with a name of "ENTER" which is also a "FLOW" Marker.

The exit() method should be placed before any return statement or as the last statement of methods without a return. exit() can be called with or without a parameter. Typically, methods that return void will use exit() while methods that return an Object will use exit(Object obj). The entry() method logs with a level of TRACE and uses a Marker with a name of "EXIT" which is also a "FLOW" Marker.

public class TestService {
  private XLogger logger = XLoggerFactory.getXLogger(TestService.class
      .getName());

  public String retrieveMessage() {
    logger.entry();

    String testMsg = getMessage(getKey());

    logger.exit(testMsg);
    return testMsg;
  }
}

This does helps in providing a more targeted API, but it's still extra lines of code for what should be automatic. As such, it only applies to the code that you can write yourself.

There's also a more subtle issue with XLogger, in that it is a class rather than an interface. As such, it's much harder to build an API on top of XLogger directly.

Annotation Based Tracing

Aspect weaving with annotations is also an option. With jcabi-aspects, you can add the @Loggable to your method, and have the appropriate logging methods woven into the code.

import com.jcabi.aspects.Loggable;

public class Resource {
  @Loggable(Loggable.TRACE)
  public String load(URL url) {
    return url.openConnection().getContent();
  }
}

The drawbacks here are that you must have a "weaving" step in your build system after compilation to incorporate aspect oriented programming, and you're still adding an explicit annotation to the method.

Again, this is only a solution when you can compile the code from source, so it does not deal with 3rd party code.

Agent Based Integration

The ideal way of dealing with tracing code is to deal with it as an instrumentation problem. Adding instrumentation to a Java program modifies the already compiled byte code so that it performs additional functionality – instrumentation is commonly used for profiling and security agents, but is fairly straightforward to pick up.

I like this approach better than the annotation or aspect-oriented programming approaches, because it is completely transparent to the code and gives the same performance as inline code.

slf4j-ext includes an agent based instrumentation that uses Javassist, but it is a broad-based agent that only logs to System.err and has to have blacklisted classes added explicitly. Instead, we'll write our own agent, using Byte Buddy.

There's two different ways to do it. You can use interception, which gives you a straightforward method delegation model, or you can use Advice, which rewrites the bytecode inline before the JVM gets to it. Either way, you can write to a logger without touching the class itself, and you can modify which classes and methods you touch.

To use interception, you use ByteBuddy like this with InfoLoggingInterceptor:

public class Interception {
  // Do it through wrapping
    public SomeLibraryClass instrumentClass() throws IllegalAccessException, InstantiationException {
        Class<SomeLibraryClass> offendingClass = SomeLibraryClass.class;
        String offendingMethodName = "doesNotUseLogging";

        return new ByteBuddy()
                .subclass(offendingClass)
                .method(ElementMatchers.named(offendingMethodName))
                .intercept(MethodDelegation.to(new InfoLoggingInterceptor()))
                .make()
                .load(offendingClass.getClassLoader(), ClassLoadingStrategy.Default.WRAPPER)
                .getLoaded()
                .newInstance();
    }

    public void doStuff() throws IllegalAccessException, InstantiationException {
        SomeLibraryClass someLibraryClass = this.instrumentClass();
        someLibraryClass.doesNotUseLogging();
    }
}

To use class advice, you do something like this with the ClassAdviceRewriter:

class AgentBased {
    public static void premain() {
        try {
            String className = "SomeOtherLibraryClass";
            String methodName = "doesNotUseLogging";

            // The debugging listener shows what classes are being picked up by the instrumentation
            Listener.Filtering debuggingListener = new Listener.Filtering(
                    new StringMatcher(className, StringMatcher.Mode.CONTAINS),
                    Listener.StreamWriting.toSystemOut());

            // This gives a bit of a speedup when going through classes...
            RawMatcher ignoreMatcher = new RawMatcher.ForElementMatchers(ElementMatchers.nameStartsWith("net.bytebuddy.").or(isSynthetic()), any(), any());

            // Create and install the byte buddy remapper
            new AgentBuilder.Default()
                    .with(new AgentBuilder.InitializationStrategy.SelfInjection.Eager())
                    .ignore(ignoreMatcher)
                    .with(debuggingListener)
                    .type(ElementMatchers.nameContains(className))
                    .transform((builder, type, classLoader, module) ->
                            builder.visit(Advice.to(ClassAdviceRewriter.class).on(named(methodName)))
                    )
                    .installOnByteBuddyAgent();
        } catch (RuntimeException e) {
            System.out.println("Exception instrumenting code : " + e);
            e.printStackTrace();
        }
    };

    public void doStuff() {
        // No code change necessary here, you can wrap completely in the agent...
        SomeOtherLibraryClass someOtherLibraryClass = new SomeOtherLibraryClass();
        someOtherLibraryClass.doesNotUseLogging();
    }
}

Here's an example program showing both approaches being used in example classes that don't have tracing enabled. I use a ThreadLocal logger here, as it gives me more control over logging capabilities than using MDC would, but there are many options available.

public class ClassWithByteBuddy {

    // This is a class we're going to wrap entry and exit methods around.
    public static class SomeLibraryClass {
        public void doesNotUseLogging() {
            System.out.println("Logging sucks, I use println");
        }
    }

    // This is a class we're going to redefine completely.
    public static class SomeOtherLibraryClass {
        public void doesNotUseLogging() {
            System.out.println("I agree, I don't use logging either");
        }
    }

    public static void main(String[] args) throws Exception {
        // Helps if you install the byte buddy agents before anything else at all happens...
        ByteBuddyAgent.install();
        AgentBased.premain();

        Logger logger = LoggerFactory.getLogger(ClassWithByteBuddy.class);
        ThreadLocalLogger.setLogger(logger);

        new Interception().doStuff();
        new AgentBased().doStuff();
    }
}

And this provides the following:

[Byte Buddy] DISCOVERY example.ClassWithByteBuddy$SomeOtherLibraryClass [sun.misc.Launcher$AppClassLoader@18b4aac2, null, loaded=false]
[Byte Buddy] TRANSFORM example.ClassWithByteBuddy$SomeOtherLibraryClass [sun.misc.Launcher$AppClassLoader@18b4aac2, null, loaded=false]
[Byte Buddy] COMPLETE example.ClassWithByteBuddy$SomeOtherLibraryClass [sun.misc.Launcher$AppClassLoader@18b4aac2, null, loaded=false]
[INFO ] e.ClassWithByteBuddy - entering: example.ClassWithByteBuddy$SomeLibraryClass.doesNotUseLogging()
Logging sucks, I use println
[INFO ] e.ClassWithByteBuddy - exit: example.ClassWithByteBuddy$SomeLibraryClass.doesNotUseLogging(), response = null
[INFO ] e.ClassWithByteBuddy - entering: example.ClassWithByteBuddy$SomeOtherLibraryClass.doesNotUseLogging()
I agree, I don't use logging either
[INFO ] e.ClassWithByteBuddy - exiting: example.ClassWithByteBuddy$SomeOtherLibraryClass.doesNotUseLogging()

And that's how you trace 3rd party code without adding any logger.trace statements.