Simplify your logging with AspectJ

Logging the conventional way

To truly appreciate the advantages offered by AspectJ, let's consider implementing logging without AspectJ. Since logging is such a common requirement, APIs and libraries are available that let us perform logging consistently. Notable examples are the standard Java logging API and log4j from Apache. These toolkits provide an efficient and abstract access to the underlying logging mechanics. They enable us to easily switch between console, socket stream, native event logging, and so forth. In addition, they allow sophisticated formatting of log messages, including the XML format. These toolkits further allow the hierarchy of logger objects and offer an easy control over the information logged.

Although these logging APIs are a significant improvement over the use of System.out.println() or other homegrown solutions, in the complete perspective, they provide only a part of the answer. To illustrate the additional work needed on our part, let's look at how we can add logging to the shopping cart example in earlier section, using the standard Java logging API.

Note: When using the standard Java logging kit, we use Logger.logp() instead of Logger.log() because of an inherent problem associated with the latter. The log() method deduces the caller class and method by examining the call stack. With the presence of an optimizing compiler and hotspot/JIT-enabled virtual machine, the deduced caller may be an incorrect one. The same problem exists with the log4j toolkit as well (with %C, %M, %F, %L, or a combined %l layout pattern). The performance hit from using the call stack for deducing a caller is also significant. The cost involves obtaining the call stack and parsing its contents--not a trivial job. See the toolkit documentation for more details.

First, we instrument each method of the Item class to log the entry into it. We choose to log each method at the Level.INFO level because we are simply writing informational entries to the log when we enter the methods. In listing 6, we change the Item class by adding code to obtain the logger object and log each method.

Listing 6: The Item class with logging enabled

import java.util.logging.*;

public class Item {

    private String _id;

    private float _price;

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

    public Item(String id, float price) {

        _id = id;

        _price = price;

    }

    public String getID() {

        _logger.logp(Level.INFO, "Item", "getID", "Entering");

        return _id;

    }

    public float getPrice() {

        _logger.logp(Level.INFO, "Item", "getPrice", "Entering");

        return _price;

    }

    public String toString() {

        _logger.logp(Level.INFO, "Item", "toString", "Entering");

        return "Item: " + _id;

    }

}

Next, similar to what we've done with the Item class, we instrument logging into the ShoppingCart class's methods, as shown in listing 7. As you can see, the changes needed for logging in both classes are the same in that every method needs to make an additional call to the logp() method.

Listing 7: The ShoppingCart class with logging enabled

import java.util.*;

import java.util.logging.*;

public class ShoppingCart {

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

    private List _items = new Vector();

    public void addItem(Item item) {

        _logger.logp(Level.INFO,

                     "ShoppingCart", "addItem", "Entering");

        _items.add(item);

    }

    public void removeItem(Item item) {

        _logger.logp(Level.INFO,

                     "ShoppingCart", "removeItem", "Entering");

        _items.remove(item);

    }

    public void empty() {

        _logger.logp(Level.INFO,

                     "ShoppingCart", "empty", "Entering");

        _items.clear();

    }

    public float totalValue() {

        _logger.logp(Level.INFO,

                     "ShoppingCart", "totalValue", "Entering");

        // unimplemented... free!

        return 0;

    }

}

Because the logging instrumentation for the Inventory, ShoppingCartOperator, and Test classes is very similar, we will not show the listings for those classes here. We now have an implementation with an entry for each method to be logged, using the standard Java logging toolkit. When you compile the classes and run the program, you get output similar to this:

> ajc *.java

> java Test

Oct 27, 2003 12:14:20 AM Test main

INFO: Entering

Oct 27, 2003 12:14:20 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:14:20 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:14:20 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:14:20 AM ShoppingCartOperator addShoppingCartItem

INFO: Entering

Oct 27, 2003 12:14:20 AM Inventory removeItem

INFO: Entering

Oct 27, 2003 12:14:20 AM ShoppingCart addItem

INFO: Entering

Oct 27, 2003 12:14:20 AM ShoppingCartOperator addShoppingCartItem

INFO: Entering

Oct 27, 2003 12:14:20 AM Inventory removeItem

INFO: Entering

Oct 27, 2003 12:14:20 AM ShoppingCart addItem

INFO: Entering

This was quite a task, right? Granted, the job was mostly mechanical.You probably copied and pasted code and modified the arguments to logp() methods. We hope you did a perfect job of changing each argument correctly; if not, you'll end up with a logging message that is inconsistent with the operation being performed.

Now consider how long it would take to introduce logging in a real system with hundreds of classes. How sure could you be that the methods would log the right information?

Logging the aspect-oriented way

Now let's use AspectJ to introduce the logging functionality into each method in all the classes in the original example. As you will see, with AspectJ-based logging, we don't have to modify our classes. All we need to do is add the aspect in listing 8 to our system, and compile it with the classes (from listings 1 through 5) using the AspectJ compiler. That's it! We now have tons of output to impress our colleagues.

Listing 8: TraceAspect performing the same job

import java.util.logging.*;

import org.aspectj.lang.*;

public aspect TraceAspect {

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

    pointcut traceMethods()

        : execution(* *.*(..)) && !within(TraceAspect);

    before() : traceMethods() {

        Signature sig = thisJoinPointStaticPart.getSignature();

        _logger.logp(Level.INFO, sig.getDeclaringType().getName(),

                     sig.getName(), "Entering");

   }

}

When we compile this aspect together with the shopping cart classes and run the test program, we get output similar to this:

> ajc *.java

> java Test

Oct 27, 2003 12:16:15 AM Test main

INFO: Entering

Oct 27, 2003 12:16:16 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:16:16 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:16:16 AM Inventory addItem

INFO: Entering

Oct 27, 2003 12:16:16 AM ShoppingCartOperator addShoppingCartItem

INFO: Entering

Oct 27, 2003 12:16:16 AM Inventory removeItem

INFO: Entering

Oct 27, 2003 12:16:16 AM ShoppingCart addItem

INFO: Entering

Oct 27, 2003 12:16:16 AM ShoppingCartOperator addShoppingCartItem

INFO: Entering

Oct 27, 2003 12:16:16 AM Inventory removeItem

INFO: Entering

Oct 27, 2003 12:16:16 AM ShoppingCart addItem

INFO: Entering

Observe the sheer amount of code we saved with AspectJ! Such modularization is possible because of AOP and AspectJ's support for programming crosscutting concerns. However, saved coding effort is not the only benefit of using AspectJ. Later in this article, we will explore all the details of logging using AspectJ and the benefits it offers.

What's wrong with conventional logging

Now that you have seen logging using conventional and AspectJ-based techniques, let's look at the shortcomings of conventional solutions. Figure 1 illustrates the overall schematic of current logging solutions. Every place that needs to log an event needs to explicitly invoke a call to the log() method of an appropriate logger. As you can see, the logging calls will be all over the core modules. When a new module is added to the system, all of its methods that need logging must be instrumented. Such instrumentation is invasive, causing the tangling of the core concerns with the logging concern. Further, if you ever happen to change the logging toolkit to a different API, you need to revisit every logging statement and modify it.

Consistency is the single most important requirement of logging. It means that if the logging specification requires that certain kinds of operations be logged, then the implementation must log every invocation of those operations. When things go wrong in a system, doubting the logging consistency is probably the last thing you want to do. Missed logging calls can make output hard to understand and sometimes useless. Achieving consistency using conventional logging is a lofty goal, and while systems can attain it initially, it requires continuing vigilance to keep it so. For example, if you add new classes to the system or new methods in existing classes, you must ensure that they implement logging that matches the current logging strategy. Figure 1 In the conventional logging solution, all log points must issue calls to the logger explicitly.