Indented Tracing Using AspectJ

Given inspiration from the book “AspectJ In Action”, I wrote a little aspect that provides indented tracing of method executions. This means that the aspect keeps track of the current indentation level in a call flow, giving an output like the following:

Entering [org.springframework.ldap.LdapTemplateListTest.]
Exiting [org.springframework.ldap.LdapTemplateListTest.]
Entering [org.springframework.ldap.LdapTemplateListTest.setUp]
  Entering [org.springframework.ldap.LdapTemplate.]
    Entering [org.springframework.ldap.DefaultNamingExceptionTranslator.]
    Exiting [org.springframework.ldap.DefaultNamingExceptionTranslator.]
  Exiting [org.springframework.ldap.LdapTemplate.]
  Entering [org.springframework.ldap.LdapTemplate.setExceptionTranslator]
  Exiting [org.springframework.ldap.LdapTemplate.setExceptionTranslator]
Exiting [org.springframework.ldap.LdapTemplateListTest.setUp]
Entering [org.springframework.ldap.LdapTemplateListTest.testList_Name]
  Entering [org.springframework.ldap.LdapTemplateListTest.expectGetReadOnlyContext]
  ...

The part that keeps track of the indentation level was written as a reusable aspect:

package org.springframework.ldap.aspects;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.JoinPoint;

/**
 * Abstract logging aspect for producing indented logging. Override the
 * loggingOperations pointcut in order to provide the joinpoints
 * where you would like the logging to be applied. Also override the methods
 * beforeLog and afterLog to provide the actual
 * logging statements. The current indentation string will be provided to these
 * methods, along with an instance of JoinPoint.
 *
 * @author Ulrik Sandberg
 */
public abstract aspect IndentedLogging {
    Log log = LogFactory.getLog("trace");

    /**
     * The current number of indentation levels.
     */
    protected int indentationlevel = 0;

    /**
     * Override and provide pointcut to log.
     */
    protected abstract pointcut loggingOperations();

    /**
     * Override and provide the actual logging statement for when the logged
     * method is entered.
     *
     * @param indent
     *            The string of spaces that provides the current indentation.
     * @param joinPoint
     *            Information about the current joinpoint.
     */
    protected abstract void beforeLog(String indent, JoinPoint joinPoint);

    /**
     * Override and provide the actual logging statement for when the logged
     * method is exited.
     *
     * @param indent
     *            The string of spaces that provides the current indentation.
     * @param joinPoint
     *            Information about the current joinpoint.
     */
    protected abstract void afterLog(String indent, JoinPoint joinPoint);

    Object around(): loggingOperations() {
        StringBuffer sb = new StringBuffer();
        if (log.isInfoEnabled()) {
            indentationlevel++;
            for (int i = 0, spaces = indentationlevel * 2; i < spaces; i++) {
                sb.append(" ");
            }
            beforeLog(sb.toString(), thisJoinPoint);
        }
        Object result;
        try {
            result = proceed();
        } finally {
            if (log.isInfoEnabled()) {
                afterLog(sb.toString(), thisJoinPoint);
                indentationlevel--;
            }
        }
        return result;
    }
}

Since the reusable aspect does all the grunt work, the actual tracing aspect becomes rather small:

package org.springframework.ldap.aspects;

import org.aspectj.lang.JoinPoint;

public aspect TraceAspect extends IndentedLogging {
    declare precedence: TraceAspect, *;

    protected pointcut loggingOperations():
        (execution(* *.*(..)) || execution(*.new(..)))
        && !within(IndentedLogging+);

    protected void beforeLog(String indent, JoinPoint joinPoint) {
        log.info(indent + "Entering ["
                + joinPoint.getSignature().getDeclaringTypeName() + "."
                + joinPoint.getSignature().getName() + "]");
    }

    protected void afterLog(String indent, JoinPoint joinPoint) {
        log.info(indent + "Exiting ["
                + joinPoint.getSignature().getDeclaringTypeName() + "."
                + joinPoint.getSignature().getName() + "]");
    }
}

Now, let’s say we don’t want to trace each and every method and constructor execution, but rather a small subset, like for example only the normal methods (no constructors) in any subclass of NameClassPairCallbackHandler. We’ll remove the execution of new from the pointcut and add the handler subclass condition:

public aspect TraceAspect extends IndentedLogging {
    declare precedence: TraceAspect, *;

    protected pointcut loggingOperations():
        execution(* *.*(..)) // just plain methods
        && !within(IndentedLogging+)
        && within(org.springframework.ldap.NameClassPairCallbackHandler+); // added
    ...

The output becomes:

Entering [org.springframework.ldap.CollectingNameClassPairCallbackHandler.handleNameClassPair]
  Entering [org.springframework.ldap.LdapTemplate$MappingCollectingNameClassPairCallbackHandler.getObjectFromNameClassPair]
  Exiting [org.springframework.ldap.LdapTemplate$MappingCollectingNameClassPairCallbackHandler.getObjectFromNameClassPair]
Exiting [org.springframework.ldap.CollectingNameClassPairCallbackHandler.handleNameClassPair]
Entering [org.springframework.ldap.CollectingNameClassPairCallbackHandler.getList]
Exiting [org.springframework.ldap.CollectingNameClassPairCallbackHandler.getList]

You might argue that it would be good to see the arguments to each call. That could easily be done by using JoinPoint.getArgs() in the tracing aspect. It would look like this:

package org.springframework.ldap.aspects;

import org.aspectj.lang.JoinPoint;

public aspect TraceAspect extends IndentedLogging {
    declare precedence: TraceAspect, *;

    protected pointcut loggingOperations():
        (execution(* *.*(..)))
        && !within(IndentedLogging+)
        && within(*..NameClassPairCallbackHandler+);

    protected void beforeLog(String indent, JoinPoint joinPoint) {
        log.info(indent + "Entering ["
                + joinPoint.getSignature().getDeclaringTypeName() + "."
                + joinPoint.getSignature().getName()
                + createParameterMessage(indent, joinPoint) + "]");
    }

    protected void afterLog(String indent, JoinPoint joinPoint) {
        log.info(indent + "Exiting ["
                + joinPoint.getSignature().getDeclaringTypeName() + "."
                + joinPoint.getSignature().getName()
                + createParameterMessage(indent, joinPoint) + "]");
    }

    private String createParameterMessage(String indent, JoinPoint joinPoint) {
        StringBuffer sb = new StringBuffer("(");
        Object[] args = joinPoint.getArgs();
        if (args.length > 0) {
            sb.append("n    " + indent);
        }
        for (int i = 0; i < args.length; i++) {
            sb.append(args[i]);
            if (i != args.length - 1) {
                sb.append(',');
            }
        }
        sb.append(")");
        return sb.toString();
    }
}

And the output would be this:

Entering [org.springframework.ldap.CollectingNameClassPairCallbackHandler.handleNameClassPair(
    o=example.com: com.example.SomeClass)]
  Entering [org.springframework.ldap.LdapTemplate$MappingCollectingNameClassPairCallbackHandler.getObjectFromNameClassPair(
      o=example.com: com.example.SomeClass)]
  Exiting [org.springframework.ldap.LdapTemplate$MappingCollectingNameClassPairCallbackHandler.getObjectFromNameClassPair(
      o=example.com: com.example.SomeClass)]
Exiting [org.springframework.ldap.CollectingNameClassPairCallbackHandler.handleNameClassPair(
    o=example.com: com.example.SomeClass)]
Entering [org.springframework.ldap.CollectingNameClassPairCallbackHandler.getList()]
Exiting [org.springframework.ldap.CollectingNameClassPairCallbackHandler.getList()]

This Post Has One Comment

  1. Meisam

    It seems nice, but I guess it has some problems.
    I tried to trace some of the benchmarks that are distributed with AspectBench Compiler (Available via http://www.sable.mcgill.ca/benchmarks/#aspectj).
    I applied this tracing aspects both Figure benchmark, and NullCheck benchmark.
    But when I run it, the program stops working after tracing some method calls.

Leave a Reply