The Holy Java

Building the right thing, building it right, fast

Archive for September, 2008

Add method tracing (params, result) to existing application w/o modifying it

Posted by Jakub Holý on September 26, 2008

Have you ever needed to learn what’s going on in a 3rd-party java application and yet didn’t want to debug it and step through it? Were you wishing to be able to see what methods get called in what order together with their actual parameters and return values? There is a "simple" solution: AspectWerkz.

Quick start:

  1. Download  AspectWerkz (I had 2.0)
  2. Create an aop.xml where you define what methods to observe
  3. (Optional) Modify the tracer class
  4. Run the target application with the aspect under Java 5 (AspectWerkz supports also older JVM but that’s more tricky):

$JRE5_HOME/bin/java
    -javaagent:lib/aspectwerkz-jdk5-2.0.jar -Daspectwerkz.definition.file=/path/to/the/aop.xml
    -cp <some jars from lib/, see below>:./bin:<your classpath>
    yourpackage.YourMainClass

 Classpath:
    aspectwerkz-core-2.0.jar
    aspectwerkz-2.0.jar
    commons-collections.jar
    commons-beanutils.jar
    commons-logging.jar
    dom4j-1.4.jar, qdox-1.4.jar, concurrent-1.3.1.jar, trove-1.0.jar (see aspectwerkz-2.0.jar’s Manifest)

 See: aspectwerkz-2.0\src\samples\examples\logging\* , aspectwerkz-2.0\src\samples\examples\proxy\tracing\*

aop.xml example:

<!--  the aspectwerkz.definition.file -->
<aspectwerkz>
    <system id="aopRunttimeLoggerExample">
        <package name="net.jakubholy.jeeutils.injectedlogger">
            <aspect class="TracingAspect ">
                <!-- Expression: any methods in the package including constructors and excluding the aspect class -->
                <pointcut name="myPointcut" expression="( execution(* org.hibernate...*(..)) OR execution(org.hibernate.tool.hbm2x...new(..)) ) AND !within(net.jakubholy.jeeutils.injectedlogger.TracingAspect) AND !within(org.hibernate.tool.hbm2x.TemplateHelper) AND !within(org.hibernate.tool.hbm2x.AbstractExporter)"/>
                <advice name="beforeMethod" type="before" bind-to="myPointcut"/>
                <advice name="afterMethod" type="after" bind-to="myPointcut"/>
            </aspect>
        </package>
    </system>
</aspectwerkz>

And now the tracing class itself:

package net.jakubholy.jeeutils.injectedlogger;

import java.util.Collection;
import java.util.Iterator;
import java.util.Map;
import org.apache.commons.beanutils.BeanUtils;
import org.codehaus.aspectwerkz.joinpoint.*;

/**
 * AspectWerkz aspect adding tracing of parameters and return values to methods.
 *
 * <p>
 * See aspectwerkz-2.0\src\samples\examples\proxy\tracing\TracingAspect.java -
 * some very good ideas.
 * </p>
 *
 * <p>
 * In AspectWerkz definition file you should define this aspect like:
 * </p>
 * <pre><code>
 *      <package name="net.jakubholy.jeeutils.injectedlogger">
            <aspect class="TracingAspect ">
                <pointcut name="myPointcut" expression="execution(* net.jakubholy...*(..)) AND !within(net.jakubholy.jeeutils.injectedlogger.TracingAspect)"/>
                <advice name="beforeMethod" type="before" bind-to="myPointcut"/>
                <advice name="afterMethod" type="after" bind-to="myPointcut"/>
            </aspect>
       </package>
 * </code></pre>
 * <p>
 * Replace 'net.jakubholy' in the execution with the package you want to
 * enable tracing for. Examples:
 * </p>
 * <ul>
 * <li>All subpackages of mypackage: <code>execution(* com.mycompany.mypackage...*(..)</code>
 * <li>All methods in MyClass: <code>execution(* com.mycompany.mypackage.MyClass.*(..)</code>
 * <li>All methods in MyClass: <code>execution(* ..MyClass.*(..)</code>
 * <li>Only myMethod in MyClass: <code>execution(* com.mycompany.mypackage.MyClass.myMethod(..)</code>
 * <li>Only public methods in mypackage: <code>execution(public * com.mycompany.mypackage...*(..)</code>
 * <li>Constructors in mypackage and below: execution(com.mycompany.mypackage...new(..)) )
 * </ul>
 *
 * TODO Add support for starting/stopping tracing when a configurable pattern (method+params+retval?) is encountered
 */
public class TracingAspect {
    private boolean doTrace = false;

    private void log(String logMsg) {
        final String threadId = "thread #" +
            Thread.currentThread().getId() + "(" + Thread.currentThread().getName() + ")";
        // TODO use asynch. loggin e.g. via Log4J's asynch. appender
        if (doTrace) System.err.println("[TracingAspect "+threadId+"] " + logMsg);
    }

    /**
     * 'Advice' called before a method or constructor.
     */
     public void beforeMethod(JoinPoint joinPoint) {
         Rtti rtti = joinPoint.getRtti();
         if (rtti instanceof MethodRtti) {
             MethodRtti methodRtti = (MethodRtti) rtti;

             if (!doTrace) {
                 doTrace = isStartTracingSignatureMatch(methodRtti);
                 log("INFO tracing enabled");
             }

             log("{BEFORE method " + methodRtti.getDeclaringType().getName() + "." + methodRtti.getName());
         } else if (rtti instanceof ConstructorRtti) {
             ConstructorRtti methodRtti = (ConstructorRtti) rtti;
             log("{BEFORE constructor " + methodRtti.getName());
         } else {
             log("{ERROR: not a method! rtti=" + rtti);
         }
     }

    /**
     * 'Advice' called after a method or constructor.
     */
     public void afterMethod(JoinPoint joinPoint) {
         Rtti rtti = joinPoint.getRtti();
         StringBuffer sb = new StringBuffer();

         if (rtti instanceof MethodRtti) {
             MethodRtti methodRtti = (MethodRtti) rtti;
             Object[] params = methodRtti.getParameterValues();
             Class[] ptypes = methodRtti.getParameterTypes();

             boolean stopTracing = doTrace && isEndTracingSignatureMatch(methodRtti);

             if (doTrace) {
                 sb.append(methodRtti.getDeclaringType().getName() + "." + methodRtti.getName() + "(");
                 // Describe parameters
                 for (int i = 0; i < params.length; i++) {
                     sb.append(ptypes[i].getName() + ": " + describe(params[i]))
                         .append((i+1 < params.length)? ", " : "");
                }

                 // Describe output
                 Object output = methodRtti.getReturnValue();
                 sb.append("): ").append(methodRtti.getReturnType().getName()).append(": ")
                     .append(describe(output));

                 // Log
                 log("AFTER method " + sb + "}");

                 if (stopTracing) {
                     log("INFO: tracing disabled; method=" + methodRtti.getName());
                     doTrace = false;
                 }
             }
         } else if (rtti instanceof ConstructorRtti) {
             ConstructorRtti methodRtti = (ConstructorRtti) rtti;
             Object[] params = methodRtti.getParameterValues();
             Class[] ptypes = methodRtti.getParameterTypes();
             sb.append("constructor " + methodRtti.getName() + "(");

             // Describe parameters
             for (int i = 0; i < params.length; i++) {
                 sb.append(ptypes[i].getName() + ": " + describe(params[i]))
                     .append((i+1 < params.length)? ", " : "");
            }
             sb.append(")");

             // Log
             log("AFTER constructor " + sb + "}");
         }
     }

     /**
      * Return a string representation of the <var>target</var>
      * containing its properties and their values.
      * @param target
      * @return
      */
     private String describe(Object target) {
         String result;
         StringBuffer sb = new StringBuffer();

         // SPECIAL: Hibernate & hbm2java generation
         // When running hbm2java, avoid InvocationTargetException <- MappingException: entity class not found <- ClassNotFoundException
         // for a class yet to generate
         if (target != null && target.getClass().getName().startsWith("org.hibernate.mapping.")) {
             return target.toString();
         } // hibernate mapping

         if (target == null) {
             result = "null";
         } else if (target.getClass().isArray()) {
             // ARRAY
             Object[] targetArray = (Object[]) target;
             sb.append("#").append(targetArray.length).append("[");

             for (int i = 0; i < targetArray.length; i++) {
                sb.append(describe(targetArray[i]));
                if (i < targetArray.length - 1) {
                    sb.append(", ");
                }
            }

             sb.append("]");
             result = sb.toString();
         } else if (target instanceof Collection) {
             Collection targetColl = (Collection) target;
             sb.append("#").append(targetColl.size()).append("[");
             for (Iterator iter = targetColl.iterator(); iter.hasNext();) {
                Object element = (Object) iter.next();
                sb.append(describe(element))
                    .append(iter.hasNext()? ", " : "");
            }
             sb.append("]");
             result = sb.toString();
         } else if (target instanceof String) {
             result = "'" + target + "'";
         } else if (target.getClass().getName().startsWith("java.lang.")) {
             result = target.toString();
         } else {
             sb.append("{");

             try {
                 final String separ = ", ";
                 Map props = BeanUtils.describe(target);
                 for (Iterator iter = props.entrySet().iterator(); iter.hasNext();) {
                    Map.Entry nameValue = (Map.Entry) iter.next();
                    if (!"class".equals(nameValue.getKey())) {
                    sb
                        .append(nameValue.getKey()).append('=')
                        .append(nameValue.getValue())
                        .append(separ);
                    }
                 } // for props

                 // remove trailing separator if present
                if (separ.equals(sb.substring( Math.max(0, sb.length() - 2 )))) {
                    sb.delete(sb.length() - 2, sb.length());
                }

             } catch (Throwable e) {
//                 e.printStackTrace();
                 sb.append("Exception examining the object ")
                     .append(target)
                     .append(": ")
                     .append(e);
                 System.err.println(sb);
             }
             sb.append("}");
             result = sb.toString();
         } // switch

         return result;
     }

     /**
      * Does the current method being instrumented match the signature
      * that should start tracing?
     * @param methodRtti
      * @return
      */
     private boolean isStartTracingSignatureMatch(MethodRtti methodRtti) {
         return true;
     }

     /**
      * Does the current method being instrumented match the signature
      * indicating we should stop tracing?
      * @param methodRtti
      * @return
      */
     private boolean isEndTracingSignatureMatch(MethodRtti methodRtti) {
         return false;// isStartTracingSignatureMatch(methodRtti);
     }
}
Advertisements

Posted in Languages | Tagged: , | 2 Comments »