Simplify your logging with AspectJ

Earlier, we discussed why we want to use the logp() method to log messages instead of log(). Another reason to use logp() is that calling the log() method would cause the logging kit to deduce that the caller is the advice instead of the advised method. This happens because the log() method uses the call stack to infer the caller. In this example, the actual caller is the advice, but we want the real caller of the logged method (that triggered the advice) to be shown in the log message and not the advice, which just happens to be the caller due to the addition of the logger aspect.

We have a robust mechanism in AspectJ that addresses all these issues. It is the thisJoinPointStaticPart object, which contains information about the captured join point's class, method, precise source location, and so forth. The compiler creates this information at compile time, and neither compiler optimization nor the presence of the JIT/hotspot virtual machine alters this information. We use the information contained in thisJoinPointStaticPart to obtain the method and class name of the logged method.

Compiling this aspect with the shopping cart source code and running the Test class results in output similar to this:

> ajc *.java

> java Test

Oct 27, 2003 12:56:18 AM Test main

INFO: Entering

Oct 27, 2003 12:56:18 AM Inventory 

INFO: Entering

Oct 27, 2003 12:56:18 AM Item 

INFO: Entering

Oct 27, 2003 12:56:18 AM Item 

INFO: Entering

Oct 27, 2003 12:56:18 AM Item 

INFO: Entering

Oct 27, 2003 12:56:18 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:56:18 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:56:18 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:56:18 AM ShoppingCart 

INFO: Entering

Oct 27, 2003 12:56:18 AM ShoppingCartOperator addShoppingCartItem

INFO: Entering

Oct 27, 2003 12:56:18 AM Inventory removeItem

INFO: Entering

Oct 27, 2003 12:56:18 AM ShoppingCart addItem

INFO: Entering

Oct 27, 2003 12:56:18 AM ShoppingCartOperator addShoppingCartItem

INFO: Entering

Oct 27, 2003 12:56:18 AM Inventory removeItem

INFO: Entering

Oct 27, 2003 12:56:18 AM ShoppingCart addItem

INFO: Entering

The output shows a message being logged as soon as the execution of the program enters each method and constructor in the system. The toolkit also prints a timestamp corresponding to each of the logged messages.

Finally, let's modify our aspect to use the log4j toolkit from Apache. This example, like the earlier one, shows how easy it is to switch from one logging toolkit to another when you use AspectJ for logging. Listing 11 shows the same logging functionality implemented using the log4j logging toolkit instead of the standard Java logging toolkit.

Listing 11: Tracing methods: the third version, using the log4j toolkit

import org.apache.log4j.*;

import org.aspectj.lang.*;

public aspect TraceAspectV3 {

    Logger _logger = Logger.getLogger("trace");

    TraceAspectV3() {

        _logger.setLevel(Level.ALL);

    }

    pointcut traceMethods()

        : (execution(* *.*(..))

          || execution(*.new(..))) && !within(TraceAspectV3);

    before() : traceMethods() {

        if (_logger.isEnabledFor(Level.INFO)) {

            Signature sig = thisJoinPointStaticPart.getSignature();

            _logger.log(Level.INFO,

                        "Entering ["

                        + sig.getDeclaringType().getName() + "."

                        + sig.getName() + "]");

        }

    }

}

The API for both toolkits is the same for the most part. Therefore, we need to change only a few statements from our earlier version (the changes appear in bold in the listing). Note that log4j does not have a logp() method; instead, the log() method, along with the use of properties file, offers the equivalent functionality. We encode the caller information in the message that is passed as an argument to the log() method call. log4j requires a properties file that specifies the information to be logged and the format for each log message. For the purpose of this test, we used the following properties file (log4j.properties) to configure log4j:

log4j.rootCategory=DEBUG, dest1

log4j.appender.dest1=org.apache.log4j.ConsoleAppender

log4j.appender.dest1.layout=org.apache.log4j.PatternLayout

When we compile the aspect in listing 11 with the rest of our classes and run the Test class, we see the following output:

> ajc *.java

> java Test

Entering [Test.main]

Entering [Inventory.<init>]

Entering [Item.<init>]

Entering [Item.<init>]

Entering [Item.<init>]

Entering [Inventory.addItem]

Entering [Inventory.addItem]

Entering [Inventory.addItem]

Entering [ShoppingCart.<init>]

Entering [ShoppingCartOperator.addShoppingCartItem]

Entering [Inventory.removeItem]

Entering [ShoppingCart.addItem]

Entering [ShoppingCartOperator.addShoppingCartItem]

Entering [Inventory.removeItem]

Entering [ShoppingCart.addItem]

The output is similar to that using the standard Java logging toolkit. You can control the information being logged, such as the addition of a timestamp or the format of the log messages, by modifying the properties file. Please refer to the log4j documentation for more details.

But there's more

In this exceprted article, we covered an overview of method tracing using AspectJ. The corresponding chapter in the book covers a lot more details to show how you can extend the mechanism for a variety of purpose such as:

• Exception logging: Since exception throwing is an important event in the system, logging the thrown exception is important. AspectJ-based solution offers a way to introduce such a functionality wihtout changing even a single line of code in the core part of the system. Similar to method tracing, you can switch the underlying logging implementation just by changing the aspect.
• Method parameter logging: To gain a better understanding of the system, often you need method arguments in addition to method name. Through use of reflective API offered by AsepctJ, you can easily log the method parameters.
• Indented logging: To improve comprehensibility of the logged output, it is desirable that the method calls in output refect the call depth, usually by indenting log messages appropriately. Through use of a simple reusable aspect, this functiuonality can be implemented quickly.

Further, the basic logging mechanism can be improved to introduce functionality such as profiling, testing, service-level monitoring and so on.

Conclusion

AspectJ-based logging is a low-investment, low-risk way to begin using AspectJ. Logging aspects also offer a unique plug-and-play nature. If this article convinced you of the benefits of using AspectJ for logging, you may start out by simply using it for debugging and tracing. Later, you can demonstrate to your team the benefits you have experienced, which may lead them to use AspectJ as well. At any point, including during the final shipment, you can exclude the AspectJ and logging aspects. The overall effect is that you can start using AspectJ with minimal risk.

Once you commit to AspectJ-based logging, you will start seeing even more benefits. You can use AspectJ-based solutions for core logging tasks that go beyond debugging and tracing. Implementation of such logging concerns is now nicely modularized. This solution leads to increased flexibility, improved accuracy, and better consistency. It saves you from the laborious and boring task of writing nearly identical log statements in code all over your system. The use of AspectJ also makes the job of choosing logging toolkits an easy task. You can start with any one that you are familiar with, and feel comfortable that changing the choice later on will require modifying only a few statements.

I welcome questions and comments! Email me at ramnivas at yahoo dot com.

Resources

[1] AspectJ in Action: Practical Aspect-oriented Programming, Ramnivas Laddad, Manning Publications, 2003.

[2] “I Want My AOP!”, Part 1-3, Ramnivas Laddad, JavaWorld, January-April, 2002. Available online at:

http://www.javaworld.com/javaworld/jw-01-2002/jw-0118-aspect.html

http://www.javaworld.com/javaworld/jw-03-2002/jw-0301-aspect2.html

http://www.javaworld.com/javaworld/jw-04-2002/jw-0412-aspect3.html

[3] “Crosscutting” (article series), Gregor Kiczales, Software Development Magazine, starting November 2003.

[4] AspectJ site including downloads and documentation: http://www.eclipse.org/aspectj

[5] AspectJ user mailing list: https://dev.eclipse.org/mailman/listinfo/aspectj-users

[6] “Design Pattern Implementation in Java and AspectJ”, Jan Hannemann and Gregor Kiczales. Proceedings of the 17th Annual ACM Conference on Object-Oriented Programming, Systems,Languages, and Applications (OOPSLA), November, 2002. Also available online at:

http://www.cs.ubc.ca/~gregor/hannemann-OOPSLA2002-aop-patterns.pdf

[7] “Aspect-Oriented Programming”, Gregor Kiczales, John Lamping, Anurag Mendhekar, Chris Maeda, Cristina Videira Lopes, Jean-Marc Loingtier, and John Irwin. Proceedings of European Conference on Object-Oriented Programming (ECOOP'97), June 1997. Available online at:

ftp://ftp.ccs.neu.edu/pub/people/crista/publications/ecoop97/for-web.pdf

[8] “Test Flexibly with AspectJ and Mock Objects”, Nicholas Lesiecki, IBM DeveloperWorks, May 2002. Available online at:

http://www-106.ibm.com/developerworks/java/library/j-aspectj2

[9] Aspect-oriented programming site: http://aosd.net

[10] Eclipse/AspectJ integration: http://www.eclipse.org/ajdt

[11] Emacs/AspectJ integration: http://aspectj4emacs.sourceforge.net

[12] JBuilder/AspectJ integration: http://aspectj4jbuildr.sourceforge.net

[13] NetBeans/AspectJ integration: http://aspectj4netbean.sourceforge.net

[14] AOSD user mailing list: http://aosd.net/mailman/listinfo/discuss