Execution Trace using Dynamic Proxy

1. Client invokes Method A, which is part of an interface.
2. The Dynamic Proxy intercepts the call, receives a call to a generic invoke method. This isthe magic sauce.
3. The dynamic proxy invokes the original method using reflection, along with more logic, e.g.logging the call.

There are two supernatural phenomena here:

• You have a class which can take any shape - each instance of the class can decide, at runtime, which interfaces it will implement.
• When the instance receives a call through any of these interfaces, it will actually receive a call to one invoke method with all the relevant details: the method which was invoked and the arguments.

Other than the above, it's all plain Java code which you control.
There are some limitations to dynamic proxies, derived directly from the way they work:

• The invocations you're tracing must be part of an interface. If not, you'll need to extract the interface. Still, even if you do, it will only work for public methods invoked by outside callers.
• You should control the instantiation of the target class' instances. It should be intercepted and replaced with your own instances.

The Debug Proxy
Sun provides an example (http://java.sun.com/j2se/1.3/docs/guide/reflection/proxy.html#examples) of tracing using dynamic proxy. I made some modifications to the code and I'm attaching my own version of a "DebugProxy". The main limitation in the original code is that it proxies only the immediate interfaces implemented by the original class. If the class extends a super-class which implements an interface, this interface will not be "proxied" (is that a word?). I also made some more modifications:

• Used Apache commons logging to do the actual logging. The logging is done "on behalf" of the original class in trace level only.
• Logging all the method arguments using toString.
• Correctly throwing exceptions: will throw the original exception that occurred.
• Using Java 5 features (Generics, for each loops, etc.).

import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Method;
import java.lang.reflect.Proxy;
import java.util.ArrayList;
import java.util.List;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class DebugProxy implements java.lang.reflect.InvocationHandler {
  private final Loglogger;
  private final Object obj;

  @SuppressWarnings("unchecked")
  public static Object newInstance(final Object obj) {
     final List<Class<?>> interfaces = new ArrayList<Class<?>>();
     Class currentClass = obj.getClass();
     while (currentClass != null) {
       if (currentClass.equals(Object.class)) {
         currentClass = null;
       } else {
         for (final Class currInterface : currentClass.getInterfaces()) {
           interfaces.add(currInterface);
         }
         currentClass = currentClass.getSuperclass();
       }
     }
     final Class<?>[] interfaceArray = new Class<?>[interfaces.size()];
     return Proxy.newProxyInstance(obj.getClass().getClassLoader(), 
               interfaces.toArray(interfaceArray), new DebugProxy(obj));
  }

  private DebugProxy(final Object obj) {
     this.obj = obj; 
     this.logger = LogFactory.getLog(obj.getClass());
  }

  public Object invoke(final Object proxy, final Method m, 
              final Object[] args) throws Throwable {
    Object result;
    try {
      if (logger.isTraceEnabled()) {
         logger.trace("Invoking "+ m.getDeclaringClass().getSimpleName() + "."
            + m.getName() + "(), args: " + argsToString(args));
      }
      result = m.invoke(obj, args);
    } catch (final InvocationTargetException e) {
      e.getCause().printStackTrace();
      throw e.getTargetException();
    } catch (final Exception e) {
      throw new RuntimeException("unexpected invocation exception: "
             + e.getMessage(), e);
    } finally { }
    return result;
  }

  private String argsToString(final Object[] args) {
    if (args == null) { return "none"; } 
    else {
      final StringBuffer sb = new StringBuffer();
      for (int i = 0; i < args.length; i++) {
         sb.append(args[i]);
         if (i < (args.length - 1)) { sb.append(", "); }
      }
      return sb.toString();
    }
  }
}

If you're not using Commons Logging, you may want to change that as well.
Next, change the instantiation on your class. Here's the example:

• Original code: MyInterface obj = new MyClass(...)
• New code: MyInterface obj = (MyInterface)DebugProxy.newInstance(new MyClass(...))

That's it. You're all set. Just execute the program and check the results in the log. After the first time, youwill have your proxy in place and the whole process becomes even simpler.

Conclusion
Using a DynamicProxy to trace runtime execution has several advantages:

• It's very simple to set up. It's laser-targeted at the class which is interesting at the moment,ignoring the rest of the system.
• You control the code, hence, you have the ultimate control on the way the events are logged. You have all the information and you can log it in any way you see fit. You can even set up a break point inside your debug proxy and intercept all the calls.
• Not much overhead on the system at runtime.

Of course, there are the limitations:

• The intercepted calls must be made through an interface.
• You need to control the instantiation of the original class.