The beauty of AspectJ-based logging
Although logging APIs solve quite a few problems, as you
have just seen they also leave some gaps. The limitations are not a result of
the logging APIs or their implementations; rather, they stem from the
fundamental limitations of objectoriented programming, which require embedding
the logging invocations in each module. AOP and AspectJ overcome those limitations.
AspectJ easily implements the invocation of logging statements from all the log
points. The beauty is that you do not need to actually instrument any log
points; writing an aspect does it automatically. Further, since there is a
central place to control logging operations, you achieve consistency easily.
The most fundamental difference between conventional logging and AspectJ-based
logging is modularization of the logging concern. Instead of writing modules
that implement core concepts in addition to invoking logging operations, with
AspectJ you write a few aspects that advise the execution of the operations in
the core modules to perform the logging. That way, the core modules do not
carry any logging-related code. By modularizing, you separate the logging
concern from the core concerns.
The solution presented here builds on available logging toolkits. For the
final act of logging, you can use any of the toolkits available. AspectJ comes
into the picture to intercept the operations, collect the context, and form a
message to pass on to the underlying logging system. Figure 2 shows the
overview of AspectJ-based logging.
With AspectJ-based logging, the logger aspect separates the core modules and
the logger object. Instead of the core modules embedding the log()
method invocations in their source code, the logger aspect weaves the
logging invocations into the core modules when they are needed. AspectJ-based
logging reverses the dependency between the core modules and the logger; it is
the aspect that encodes how the operations in the core modules are logged
instead of each core module deciding for itself.
Developing logging and tracing aspects
Tracing is a special form of logging where the entry and/or exit of selected
methods are logged. Tracing is useful during the development phase in order to
understand system behavior, especially when a debugger is not an option, either
due to the speed at which the activities occur or due to the distributed nature
of the application. In this section, we will examine method tracing and
exception logging. We will also use these examples to show how you can
accomplish the task using different logging toolkits. These snippets will
enable you to try logging for your own system.
Method call tracing
Let's develop an aspect that will enable tracing method calls in any system.
Simply compile this aspect with the rest of the code and you will see the
logging of every method call. No changes will be needed in any of your classes.
Our first version, in listing 9, uses System.out
as the logging stream.
Listing 9: Tracing methods: the first version, using
System.out as the logging stream
import org.aspectj.lang.*;
public aspect TraceAspectV1 { pointcut traceMethods() //1
: (execution(* *.*(..)) //1
|| execution(*.new(..))) && !within(TraceAspectV1); //1
before() : traceMethods() { Signature sig = thisJoinPointStaticPart.getSignature(); //2
System.out.println("Entering [" //2 + sig.getDeclaringType().getName() + "." //2
+ sig.getName() + "]"); //2
}
}
- Traced methods pointcut:
The traceMethods() pointcut captures the calls to methods
that need tracing--in our case, it will be all the methods in the system. The !within(TraceAspectV1) part helps us avoid
recursion caused by tracing method calls in the aspect itself. Once we
compile the aspect along with the core modules, a log message will print
to System.out before any method is executed. We could also, if required,
easily produce a log message after the method execution by adding an after
advice.
- Log advice: We use thisJoinPointStaticPart to get
information about the method captured by the pointcut. The method getSignature() on thisJoinPointStaticPart
returns the signature of the captured method. We use this object to
get the name of the class and method to form and print the log message.
When we run this aspect with our shopping cart example, we get 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]
Now let's modify the aspect to use the standard Java logging toolkit so that
we can use the features it offers, such as the ability to dynamically modify
the logging level. Note that we can introduce such a change to the whole system
by modifying just a few lines in one aspect. Without AspectJ, we would have to
modify every log statement in the system. In listing 10, we show how you can
use the standard logging toolkit to perform logging that is identical in functionality
to that in listing 9.
Listing 10: Tracing methods: the second version, using
the standard logging toolkit
import java.util.logging.*;
import org.aspectj.lang.*;
public aspect TraceAspectV2 { private Logger _logger = Logger.getLogger("trace");
TraceAspectV2() { _logger.setLevel(Level.ALL);
}
pointcut traceMethods()
: (execution(* *.*(..))
|| execution(*.new(..))) && !within(TraceAspectV2);
before() : traceMethods() { if (_logger.isLoggable(Level.INFO)) { Signature sig = thisJoinPointStaticPart.getSignature();
_logger.logp(Level.INFO,
sig.getDeclaringType().getName(),
sig.getName(),
"Entering");
}
}
}
The aspect in listing 10 contains a logger object, and the constructor sets
its logging level to an initial value. This logging level is only the initial
level; any part of the system can later get hold of the "trace"
logger object using Logger. getLogger("trace")
and modify its level. Therefore, before we perform the actual logging, advice
to the traceMethods() pointcut first checks if the current
logging level is such that the logp()
method call will result in a log message. It does this by calling isLoggable(). The check for the log level is needed for
performance reasons only. It ensures that we do not perform a wasteful
operation in assembling the log message if the message will not be logged. To
perform the actual logging, we invoke the logp()
method on the logger object with the appropriate log message and caller
information.
IE 7
Firefox 2.0
