Using an Aspect for Wrapping Method Logging
Overview
A good practice when developing your Java code is to log the entry and exit of your class methods for purposes of debugging. The challenge is that logging the entry and exit of every method is time-consuming, not only during initial method creation but also during re-factoring. How can you accomplish debugging your methods quickly and efficiently? Aspects.
If you have not heard of Aspects before or have not used them, I recommend starting with the following resources:
http://stackoverflow.com/questions/242177/what-is-aspect-oriented-programming
http://www.javacodegeeks.com/2012/06/simple-introduction-to-aop.html
Writing the Aspect
There are several key parts to the aspect we are going to write:
- We need to create an annotation that can be used on classes and methods that we don’t want to log. An example where exclusion is important is for objects managed by a persistence mechanism, such as Hibernate. Logging these types of objects could result in unnecessary and expensive fetches in the relationship graph.
- We need to create the aspect
- We need to add pointcut expressions for each of the execution types that we want to include and exclude from logging.
- We need to implement before and after advice on our pointcut expressions. This is where the actual logging is performed.
Annotation
The code for our annotation is below:
1: package com.company;
2: import java.lang.annotation.ElementType;
3: import java.lang.annotation.Retention;
4: import java.lang.annotation.RetentionPolicy;
5: import java.lang.annotation.Target;
6: /**
7: * Annotating a class or method with @DebugExclude will result in the
8: * class or method being ignored by the DebugMethodAspect
9: *
10: * @see DebugMethodAspect
11: */
12: @Target( { ElementType.TYPE, ElementType.METHOD })
13: @Retention(RetentionPolicy.CLASS)
14: public @interface DebugExclude {}
The annotation is pretty simple. Per line 12, we have configured the annotation to be usable both on types and annotations. Again, annotating a class or method with @DebugExclude will result in the class or method not being logged by the DebugMethodAspect aspect.
Aspect
With the annotation complete, let’s write the code for DebugMethodAspect:
1: package com.company;
2:
3: import org.apache.commons.logging.Log;
4: import org.apache.commons.logging.LogFactory;
5: import org.aspectj.lang.JoinPoint;
6: import org.aspectj.lang.Signature;
7: import org.aspectj.lang.annotation.AfterReturning;
8: import org.aspectj.lang.annotation.Aspect;
9: import org.aspectj.lang.annotation.Before;
10: import org.aspectj.lang.annotation.Pointcut;
11: import org.aspectj.lang.reflect.CodeSignature;
12:
13: /**
14: * Aspect for debugging the entry and exit of a method.
15: */
16: @Aspect
17: public class DebugMethodAspect {
18:
19: private static final Log LOGGER = LogFactory.getLog(
20: com.company.CommonLoggingClass.class);
21:
22: /**
23: * All methods within com.company.application.*
24: */
25: @Pointcut("execution ( * com.company.application..* (..))")
26: public void allMethods() {}
27:
28: /**
29: * All @DebugExclude types or join points where the code executing
30: * has @DebugExclude
31: */
32: @Pointcut("@annotation(DebugExclude) || within(@DebugExclude *)")
33: public void debugExclude() {}
34:
35: /**
36: * All toString methods
37: */
38: @Pointcut("execution (String toString())")
39: public void toStringMethod() {}
40:
41: /**
42: * Logs all method entries, except for types/methods with
43: * @DebugExclude and toString methods.
44: *
45: * @param jp JoinPoint
46: */
47: @Before(value = "allMethods() && !debugExclude() &&
48: !toStringMethod()")
49: public void beforeDebug(final JoinPoint jp) {
50: if (LOGGER.isDebugEnabled()) {
51: CodeSignature sig = (CodeSignature) jp.getSignature();
52: LOGGER.debug("Entering: " + sig.getDeclaringTypeName() +
53: "." + sig.getName());
54: Object[] args = jp.getArgs();
55: if (args != null) {
56: try {
57: String[] names =
58: ((CodeSignature) jp.getSignature()).
59: getParameterNames();
60: for (int i = 0; i < args.length; i++) {
61: LOGGER.debug("Entering Argument - [" + names[i] + "]: " +
62: args[i]);
63: }
64: } catch (Throwable t) { }
65: }
66: }
67: }
68:
69: /**
70: * Logs all method exits, except for types/methods with
71: * @DebugExclude and toString methods.
72: *
73: * @param jp JoinPoint
74: * @param returning the object being returned from the method
75: */
76: @AfterReturning(pointcut = "allMethods() && !debugExclude()
77: && !toStringMethod()", returning = "returning")
78: public void afterDebug(final JoinPoint jp, final Object returning) {
79: if (LOGGER.isDebugEnabled()) {
80: Signature s = jp.getSignature();
81: LOGGER.debug("Exiting: " + returning);
82: LOGGER.debug("Exiting Result: " + s.getDeclaringTypeName() +
83: "." + s.getName());
84: }
85: }
86: }
Let's look at the key lines of this code:
- In line 16, i've annotated the class with @Apsect. In my implementations, I normally leverage Spring AOP, which when configured correctly should manage this aspect for you.
- In line 19-20, an Apache Commons Logging Log instance is created. You can, of course, use any logging framework of your choice. While I have not included it in the blog post, I created an empty class called CommonLoggingClass, which, as the name implies, is used as the common class name in the log entries.
- In line 25, I define the first of three pointcut expressions. The expression simply matches all join points that are in the package com.company.application.
- In line 32, I define the second of three pointcut expressions. The expression simply matches all join points where the annotation @DebugExclude has been applied.
- In line 38, the last of the pointcut expressions is defined. This expression matches the toString method on a class.
- In line 47, I define the before advice. As you can see, the advice is applied for all methods that are not excluded by the @DebugExclude annotation and not a toString method.
- In line 76, logic similar to that of line 47 applies the after returning advice for all methods that are not excluded by the @DebugExclude annotation and not a toString method.
- The logic for the beforeDebug and afterDebug methods should be pretty straight-forward for you. In beforeDebug, the method and method signature are logged and in afterDebug, the exit return is logged.
Conclusion
Hopefully this aspect definition gives you a good approach for quickly and easily wrapping your methods for debugging.
