Add Logging at Class Load Time with Java Instrumentation Blog

Version 2


    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)) {"> main(args=" + Arrays.asList(args) + ")"); } System.out.println("Hello World"); if (_log.isLoggable(Level.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.

    Using the Java Instrumentation API

    You can invoke Java with the JVM arguments-javaagent:youragent.jar or-javaagent:youragent.jar=argument to have Java call the premain(...) method listed in the manifest ofyouragent.jar before trying to run the mainmethod specified. This premain(...) method then allows you to register a class file transformer with the system class loader, which provides a transform(...) method. This method is then called as a part of loading each and every class from then on, and may manipulate the actual byte codes before it is processed by the class loader into a realClass.

    For this to work you must have several pieces in place:

    A class implementingClassFileTransformer.
    The transform(...) method will be called for each class as it is being loaded. The argument is the complete, original byte code for the whole class.
    A class providing a static void premain()method.
    The premain(...) method must register the above transformer with the class loader. It can also handle the argument provided at the command line.
    A correct MANIFEST.MF file.
    The MANIFEST.MF must contain a Pre-Class: .. line referring to the class with thepremain() method. Additionally, useBoot-Class-Path: to refer to external .jar files.

    The code must be put into a .jar file with this manifest. If not, it will silently fail.

    Thecom.runjva.instrumentation.LoggerAgent Sample Agent

    This section lists a sample agent namedcom.runjva.instrumentation.LoggerAgent. It implements the java.lang.instrument.ClassFileTransformerinterface and provides the premain(...) method required.

    The actual byte code manipulation in thetransform(...) method is done with the JBoss "Javassist" library, which provides both a Java snippet compiler and high-level byte code manipulation routines. The compiler allows us to do the manipulation by creating Java string snippets that are then compiled and inserted at the appropriate location.

    The signature extraction and return value type extraction methods are rather complex and have been placed incom.runjva.instrumentation.JavassistHelper, which is not listed but available in the sample code .zip file.

    See the Resources section for the sample code and links to Javassist and background articles.

    This is the com.runjva.instrumentation.LoggerAgentclass:

    package com.runjva.instrumentation; import java.lang.instrument.*; import java.util.*; import javassist.*; public class LoggerAgent implements ClassFileTransformer { public static void premain(String agentArgument, Instrumentation instrumentation) { if (agentArgument != null) { String[] args = agentArgument.split(","); Set argSet = new HashSet(Arrays.asList(args)); if (argSet.contains("time")) { System.out.println("Start at " + new Date()); Runtime.getRuntime().addShutdownHook(new Thread() { public void run() { System.out.println("Stop at " + new Date()); } }); } // ... more agent option handling here } instrumentation.addTransformer(new LoggerAgent()); } 

    The premain(...) method is responsible for adding the LoggerAgent as a class transformer. It also considers the string argument as a comma-separated list of options and if the option time is given, the date is printed now and at shutdown time.

    String def = "private static java.util.logging.Logger _log;"; String ifLog = "if (_log.isLoggable(java.util.logging.Level.INFO))"; String[] ignore = new String[] { "sun/", "java/", "javax/" }; public byte[] transform(ClassLoader loader, String className, Class clazz, domain, byte[] bytes) { for (int i = 0; i < ignore.length; i++) { if (className.startsWith(ignore[i])) { return bytes; } } return doClass(className, clazz, bytes); } 

    The transform(...) method is called for every class loaded by the system class loader just before being instantiated into a real object. Each class contains code to load those classes it needs, so to avoid adding loggers to the runtime library classes, it is necessary to look at the class name and return library classes unmodified (note that the separators are slashes, not dots).

    private byte[] doClass(String name, Class clazz, byte[] b) { ClassPool pool = ClassPool.getDefault(); CtClass cl = null; try { cl = pool.makeClass(new; if (cl.isInterface() == false) { CtField field = CtField.make(def, cl); String getLogger = "java.util.logging.Logger.getLogger(" + name.replace('/', '.') + ".class.getName());"; cl.addField(field, getLogger); CtBehavior[] methods = cl.getDeclaredBehaviors(); for (int i = 0; i < methods.length; i++) { if (methods[i].isEmpty() == false) { doMethod(methods[i]); } } b = cl.toBytecode(); } } catch (Exception e) { System.err.println("Could not instrument " + name + ", exception : " + e.getMessage()); } finally { if (cl != null) { cl.detach(); } } return b; } 

    The doClass(...) method uses Javassist to analyze the byte stream provided. If it is a real class (as opposed to an interface), a logger field named _log is added and initialized to the name of the class. Each non-empty method is then processed with doMethod(...). The finallyclause ensures that the class definition is removed again from the Javassist pools to keep memory usage down.

    private void doMethod(CtBehavior method) throws NotFoundException, CannotCompileException { String signature = JavassistHelper.getSignature(method); String returnValue = JavassistHelper.returnValue(method); method.insertBefore(ifLog + "\">> " + signature + ");"); method.insertAfter(ifLog + "\"<< " + signature + returnValue + ");"); } }

    The doMethod(...) class creates if (_log.isLoggable(INFO)) snippets to insert at the beginning and end of each method. This level has been chosen as it is the lowest level that generates output without any configuration of the logging system.

    Note that the JavassistHelper class is available in the sample code .zip file (see Resources).

    The Sample MANIFEST.MFFile

    Only two lines are needed here: one to point to the class with the premain method, and one to make Javassist available to the agent.

    Premain-Class: com.runjva.instrumentation.LoggerAgent Boot-Class-Path: ../lib/javassist.jar 

    Note that the dist/loggeragent.jar needs tolib/javassist.jar--hence the ../lib relative path.

    The Sample build.xml File

    The build.xml file contain a compilation target, a .jar target, a traditional HelloWorld target, and aHelloWorld target with the logger agent active.

    <project name="Logger Agent (Java 5+)" default="all"> <target name="all" depends="compile,jar,withoutAgent,withAgent"/> <target name="withAgent" description="run with logging added by java agent"> <java fork="yes" classpath="bin" classname="com.runjva.demo.HelloWorld"> <jvmarg value="-javaagent:dist/loggeragent.jar=time"/> </java> </target> <target name="withoutAgent" description="run normally"> <java fork="yes" classpath="bin" classname="com.runjva.demo.HelloWorld"> </java> </target> <target name="compile" description="compile classes"> <delete dir="bin" /> <mkdir dir="bin" /> <javac source="1.4" srcdir="src" destdir="bin" debug="true" optimize="true" verbose="false" classpath="lib/javassist.jar"> </javac> </target> <target name="jar" depends="compile" description="create agent jar"> <jar basedir="bin" destfile="dist/loggeragent.jar" manifest=""/> </target> </project>

    Running ant gives output similar to:

    Buildfile: build.xml compile: [delete] Deleting directory /home/ravn/workspace/com.runjva.instrumentation/bin [mkdir] Created dir: /home/ravn/workspace/com.runjva.instrumentation/bin [javac] Compiling 3 source files to /home/ravn/workspace/com.runjva.instrumentation/bin jar: [jar] Building jar: /home/ravn/workspace/com.runjva.instrumentation/dist/loggeragent.jar withoutAgent: [java] Hello World withAgent: [java] Start at Fri Apr 18 21:13:53 CEST 2008 [java] 18-04-2008 21:13:54 com.runjva.demo.HelloWorld main [java] INFO: >> main(args=[]) [java] Hello World [java] 18-04-2008 21:13:54 com.runjva.demo.HelloWorld main [java] INFO: << main(args=[]) [java] Stop at Fri Apr 18 21:13:54 CEST 2008 all: BUILD SUCCESSFUL Total time: 2 seconds

    The output shows that the logging statements have been added and that they actually generate output. The actual order of the statements may change from run to run, as the log statements are written to System.err and the timing info, as well as the output from HelloWorld, is written toSystem.out.


    The Java Instrumentation API can be used to transparently add method-call logging to any Java code at runtime without changing the source code or the compiled byte code. By automating the generation of log statements, it is guaranteed that they are always up to date and the programmers are relieved of this tedious task.