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
About the Author
Ramnivas Laddad has been developing complex software systems for over a
decade. He is an active member of the AspectJ user community and has
been involved with aspect-oriented programming from its early form.
Ramnivas has authored several articles, papers, and books. His most
recent publication, "AspectJ in Action: Practical aspect-oriented
programming" (Manning, 2003) has been labeled as the most useful guide
to AOP/AspectJ. Ramnivas is also a mentor at AspectMentor, a consortium
of AOP experts who provide assistance with training, consulting, and
mentoring.
