Simplify your logging with AspectJ

(Excerpted from AspectJ in Action by Ramnivas Laddad)

Logging is one of the most common techniques that we use to understand a system's behavior. In its simplest form, logging prints messages describing the operations performed. For example, in a banking system, you would log each account transaction with information such as the nature of the transaction, the account number, and the transaction amount. During the development cycle, logging plays a role similar to a debugger. It is also usually the only reasonable choice for debugging distributed programs. By examining the log, a developer can spot unexpected system behavior and correct it. A log also helps the developer see the interaction between different parts of a system in order to detect exactly where the problem might be. Likewise, in fully deployed systems, logging acts as a diagnostic assistant for finding the root cause of the problem.

Currently used mechanisms implement logging along with the operation's core logic, which is tangled with the logging statements. Further, changing the logging strategy often requires changing many modules. Since logging is a crosscutting concern (a requirement, design element, or implementation that span multiple modules), aspect-oriented programming (AOP) and AspectJ can help modularize it. With AspectJ, you can implement the logging mechanism independent of the core logic. AspectJ simplifies the logging task by modularizing its implementation and obviating the need to change many source files when requirements change. AspectJ not only saves a ton of code, but also establishes centralized control, consistency, and efficiency. Implementing logging with AspectJ--a safe and relatively simple task--is a good way to learn AOP and AspectJ and to introduce it into your organization. The next time you encounter some unexpected problem that occurs infrequently, you can use AspectJ-based logging to easily monitor the operation log and isolate the problem. Once the problem is fixed, you can just as easily remove logging. In this article, we demonstrate how you'd use AspectJ in implementing logging. The solution presented here builds on the standard logging APIs.

A quick overview of the AspectJ language

Since AspectJ is still a new language, in this section, we will take a quick look at the AspectJ language. See the Resources section for books and articles that provide more information about AOP and the AspectJ programming langiage.

AspectJ uses extensions to the Java programming language to specify the weaving rules. The extensions are designed in such a way that a Java programmer should feel at home while using them. The AspectJ extensions use the following constructs to specify the weaving rules programmatically; they are the building blocks that form the modules that express the crosscutting concern’s implementation.

Join point

A join point is an identifiable point in the execution of a program. It could be a call to a method or an assignment to a member of an object. In AspectJ, everything revolves around join points, since they are the places where the crosscutting actions are woven in. Let’s look at some join points in this code snippet:

public class Account {

    ...

    void credit(float amount) {

        _balance += amount;

    }

}

The join points in the Account class include the execution of the credit() method and the access to the _balance instance member.

Pointcut

A pointcut is a program construct that selects join points and collects context at those points. For example, a pointcut can select a join point that is a call to a method, and it could also capture the method’s context, such as the target object on which the method was called and the method’s arguments.

We can write a pointcut that will capture the execution of the credit() method in the Account class shown earlier:

execution(void Account.credit(float))

The pointcut construct in AspectJ allows use of a few wildcards to capture related set of join points. For example, the following pointcut captures the execution of all methods in Account class and its subclasses:

execution(void Account+.*(..))

Advice

Advice is the code to be executed at a join point that has been selected by a pointcut. Advice can execute before, after, or around the join point. Around advice can modify the execution of the code that is at the join point, it can replace it, or it can even bypass it. Using an advice, we can log a message before executing the code at certain join points that are spread across several modules. The body of advice is much like a method body--it encapsulates the logic to be executed upon reaching a join point.

Using the earlier pointcut, we can write advice that will print a message before the execution of the credit() method in the Account class:

before() : execution(void Account.credit(float)) {

    System.out.println("About to perform credit operation");

}

Introduction

The introduction is a static crosscutting instruction that introduces changes to the classes, interfaces, and aspects of the system. It makes static changes to the modules that do not directly affect their behavior.

For example, you can add a method or field to a class.

The following introduction declares the Account class to implement the BankingEntity interface:

declare parents: Account implements BankingEntity;

Compile-time declaration

The compile-time declaration is a static crosscutting instruction that allows you to add compile-time warnings and errors upon detecting certain usage patterns. For example, you can declare that it is an error to call any Abstract Window Toolkit (AWT) code from an EJB.

The following declaration causes the compiler to issue a warning if any part of the system calls the save() method in the Persistence class. Note the use of the call() pointcut to capture a method call:

declare warning : call(void Persistence.save(Object))

                : "Consider using Persistence.saveOptimized()";

Aspect

The aspect is the central unit of AspectJ, in the same way that a class is the central unit in Java. Pointcuts, advice, introductions, and declarations are combined in an aspect. In addition to the AspectJ elements, aspects can contain data, methods, and nested class members, just like a normal Java class.

We can merge all the code examples from this section together in an aspect as follows:

public aspect ExampleAspect {

    before() : execution(void Account.credit(float)) {

        System.out.println("About to perform credit operation");

    }

    declare parents: Account implements BankingEntity;

    declare warning : call(void Persistence.save(Object))

        : "Consider using Persistence.saveOptimized()";

}

Let’s take a look at how this all functions together. When you’re designing a crosscutting behavior, the first thing you need to do is identify the join points at which you want to augment or modify the behavior, and then you design what that new behavior will be. To implement this design, you first write an aspect that serves as a module to contain the overall implementation. Then, within the aspect, you write pointcuts to capture the desired join points. Finally, you create advice for each pointcut and encode within its body the action that needs to happen upon reaching the join points. You may use introduction and compile-time declarations to support the implementation.

For example, consider an e-commerce implementation where you want to write an aspect to log the execution of all public methods. First, you create the aspect that will encapsulate the logging crosscutting concern. You then write a pointcut in the aspect to capture all join points for the public operations in the desired set of classes. Finally, in the aspect, you write an advice to this pointcut and, within its body, you print a logging statement. If you wanted to keep some logging-specific state in the logged classes, such as the number of method executions in each class, you could use a static introduction within the aspect to add an integer data member to all classes being logged. The advice could then update and read this integer field and print it to the logging stream.