Aspect J Maven and Logging

At my earlier job, I had looked at Aspect Oriented programming with Spring. I used the same for transactions. I wanted to use it for Logging method enter/exits as well but abandoned the same as one would need to use Spring's native AspectJ weaving. I was not ready to take that on at the time. Another option was to use AspectJ compile-time weaving, again, not something I had the time for and simply settled on Transactional support with Spring Aspects.

So what am I upto? I wanted to play with AspectJ and how compile time weaving on maven project would help me eliminate the logging.

Enter and exit of methods are quite useful, especially when debugging. Another use case of debugging would be to trace the method arguments passed to a method. In addition, performance of profiling method executions has its benefits. In an earlier blog post I had investigated the use of Java Instrumentation to assist with profiling.

So I start by creating a logging Aspect. If the logging level is set as DEBUG, it will LOG entry and exit of a method. If the level is set as TRACE, then the time for method execution is also logged along with the method arguments to the method. The following represents the Aspect:

---

import org.aspectj.lang.*;
import org.apache.log4j.*;

public aspect LoggingAspect {

  Logger LOG = Logger.getLogger("trace");
  
  // Execute on all methods except this Logging Aspect

  pointcut traceMethods()
        : execution(* *.*(..)) && !within(LoggingAspect);

  // Around each method do the following
  Object around() : traceMethods() {

    Signature sig = thisJoinPointStaticPart.getSignature();
    
    String baseEnterMessage = "Enter [" + sig.getDeclaringType().getName() + "." + sig.getName() + "] ";

    
    if (LOG.isTraceEnabled()) {
      Object[] args = thisJoinPoint.getArgs();

      
      if (args.length > 0) {
        StringBuilder argsBuilder = new StringBuilder(20);

        argsBuilder.append(baseEnterMessage).append(" Args :");
        
        for (int i = 0; i < args.length; i++) {

          argsBuilder.append("{Index [" + i + "], Value [" + args[i] + "]}");

          if (i != args.length - 1) {

            argsBuilder.append(",");
          }
        }        
        argsBuilder.append("}");

        
        LOG.trace(argsBuilder.toString());  
      } 
      else {

        LOG.trace(baseEnterMessage);
      }
    }
    else if (LOG.isDebugEnabled()) {

      // Print base debug without arguments
      LOG.debug(baseEnterMessage);
    }
    
    long start = System.currentTimeMillis();

   
    try {
      Object result = proceed();     
      return result;

    } finally {
      String baseMessage = "Exiting [" + sig.getDeclaringType().getName() + "." + sig.getName() + "].";

     
      if (LOG.isTraceEnabled()) {
        // If trace is enabled, print the time for execution.
        long end = System.currentTimeMillis();

        LOG.trace(baseMessage + "Completed in:" + (end - start) + " millis");

      } else if (LOG.isDebugEnabled()) {        
        LOG.debug(baseMessage);

      } 
    }
  }

---

Another nice use of Aspects is to be able to enforce compile time standard checks. Maybe Find Bugs has a way to already do this. Not sure. Anyway, say for example, we want to detect when there are System.out.println() calls in the code or maybe the code in question is using some Class/Framework that we do not approve of, with Aspects and compile time checking there is a nice way out. I quite liked reading the blog by Jacob Matute on the compile time enforcement of standards. What I envision is the inclusion of a simple jar in project that can/will enforce the standards one desires. I think this might be preferable over depending on IDE based configuration of plugins.

What about method invocations where checks are performed? For example in many methods we repeat code that checks if an argument is null and throws some exception? What if one could declare an annotation on the method and an aspect check for the annotation to handle the same for you? The code becomes cleaner IMO. I think Java 7 will have this feature. Till then one can create an @NotNull annotation on a parameter and have aspects handle the exception throwing part for you across your entire code base. Andy Clement's blog discusses the same very nicely.

As I used maven for all my projects, there is a plugin from codehaus, for integrating AspectJ into maven.

For the sake of demonstration, I have a simple, fictional and potentially farcical objects that would undergo the tests of the Aspects:

---

public class Order {
  private final Long id;

  private final String userName;
  private final Random random = new Random();

  
  public Order(Long id, String userName) {
    this.id = id;

    this.userName = userName;
  }

  public String getUserName() { return userName; }

  
  public int getTotalCost(int range) {
    System.out.println("Calculating Cost...");

    try {
      Thread.sleep(2000L);
    } catch (InterruptedException e) {}

    return getRandom(range);
  }
  
  private int getRandom(int range) { return random.nextInt(range);}

}

---

An even trivial use of the Order object which is not even a unit test is shown below:

---

@Test
public void testOrderModel() {

 Order order = new Order(23L, "Foo");

 System.out.println("Order UserName:" + order.getUserName());

 System.out.println("Order Total cost:" + order.getTotalCost(113));

 System.out.println(Util.concatName("Sanjay", "Acharya"));

}

---

When I run "mvn install", I notice the following depending on the logging level I have setup in my log4j.properties, i.e., DEBUG or TRACE:

---

-------------------------------------------------------
 T E S T S                                             
-------------------------------------------------------
Running com.welflex.model.ModelTest                    
Enter [com.welflex.model.Order.getUserName]            
Exiting [com.welflex.model.Order.getUserName].Completed in:0 millis
Order UserName:Foo
Enter [com.welflex.model.Order.getTotalCost]  Args :{Index [0], Value [113]}}
Calculating Cost...
Enter [com.welflex.model.Order.getRandom]  Args :{Index [0], Value [113]}}
Exiting [com.welflex.model.Order.getRandom].Completed in:0 millis
Exiting [com.welflex.model.Order.getTotalCost].Completed in:2000 millis
Order Total cost:40
Enter [com.welflex.model.Util.concatName]  Args :{Index [0], Value [Sanjay]},{Index [1], Value [Acharya]}}
Exiting [com.welflex.model.Util.concatName].Completed in:1000 millis
SanjayAcharya
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.12 sec

---

Parting Thoughts:
I think Aspects are rather powerful. There is plugin support for Aspects as well. For cross cutting concerns, use of Aspects is the way to go IMHO. Finally, although this is a maven project using JDK 1.5, there is no reason why this applies to maven only or cannot be used on previous versions of the JDK.

A maven project that demonstrates the above is available for download HERE. One problem that I faced was getting the maven-aspectj plugin to install correctly. If you do install the same, you might want to add the codehaus repository to the pom.xml to ensure that the plugin is downloaded. To execute the project, from your command line, issue a "mvn install". There is a log4j.properties file in the project whose logging level you can tweak to see differences.

Enjoy :-)!