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:
- Application Logging in Java: Creating a Logging Framework
- Application Logging in Java: Adding Configuration
- Application Logging in Java: Converters
- Application Logging in Java: Markers
- Application Logging in Java: Appenders
- Application Logging in Java: Logging Costs
- Application Logging in Java: Encoders
- Application Logging in Java: Tracing 3rd Party Code
- Application Logging in Java: Filters
- Application Logging in Java: Putting it all together
Rather than defining tracing, let's give a demonstration. If you wrap your code in this:
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.
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
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.
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
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.
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
To use class advice, you do something like this with the
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.
And this provides the following:
And that's how you trace 3rd party code without adding any