Add Logging at Class Load Time with Java Instrumentation

When you're trying to analyze why a program failed, a very valuable piece of information is what the program was actually doing when it failed. In many cases, this can be determined with a stack trace, but frequently that information is not available, or perhaps what you need is information about the data that was being processed at the time of failure.

Traditionally this means using a logging framework like log4j or the Java Logging API, and then writing and maintaining all necessary log statements manually. This is very tedious and error-prone, and well-suited for automation. Java 5 added the Java Instrumentation mechanism, which allows you to provide "Java agents" that can inspect and modify the byte code of the classes as they are loaded.

This article will show how to implement such a Java agent, which transparently will add entry and exit logging to all methods in all your classes with the standard Java Logging API. The example used is Hello World:

public class HelloWorld {
public static void main(String args[]) {
System.out.println("Hello World");
}
}



And here is the same program with entry and exit log statements added:


import java.util.Arrays;
import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggingHelloWorld {
final static Logger _log = Logger.getLogger(LoggingHelloWorld.class.getName());

public static void main(String args[]) {
if (_log.isLoggable(Level.INFO)) {
_log.info("> main(args=" + Arrays.asList(args) + ")");
}
System.out.println("Hello World");
if (_log.isLoggable(Level.INFO)) {
_log.info("< main()");
}
}
}



The default logger format generates output similar to:

2007-12-22 22:08:52 LoggingHelloWorld main
INFO: > main(args=[])
Hello World
2007-12-22 22:08:52 LoggingHelloWorld main
INFO: < main()


Note that each log statement is printed on two lines. First, a line with a time stamp, the provided log name, and the method in which the call was made, and then a line with the provided log text.

The rest of the article will demonstrate how to make the original Hello World program behave like the logging Hello World by manipulating the byte code when it is loaded. The manipulation mechanism is the Java Instrumentation API added in Java 5.