How to use AOP with AspectJ for logging?

Question

I would like to add "trace" messages to all my public methods as follows:

public void foo(s:String, n:int) { // log is a log4j logger or any other library
  log.trace(String.format("Enter foo with s: %s, n: %d", s, n))
  ...
  log.trace("Exit foo") 
}

Now I would like to add all those log.trace to my methods automatically with AOP (and byte code instrumentation). I am thinking about AspectJ. Does it make sense? Do you know any open-source, which does exactly that?

Solution 1

I have created a simple aspect to capture the execution of public methods. The core of this AspectJ code is the pointcut definition:

pointcut publicMethodExecuted(): execution(public * *(..));

Here we are capturing all public methods with any return type, on any package and any class, with any number of parameters.

The advice execution could be visualized on code snippet below:

after(): publicMethodExecuted() {
    System.out.printf("Enters on method: %s. \n", thisJoinPoint.getSignature());

    Object[] arguments = thisJoinPoint.getArgs();
    for (int i =0; i < arguments.length; i++){
        Object argument = arguments[i];
        if (argument != null){
            System.out.printf("With argument of type %s and value %s. \n", argument.getClass().toString(), argument);
        }
    }

    System.out.printf("Exits method: %s. \n", thisJoinPoint.getSignature());
}

This advice use thisJoinPoint to get the method signature and arguments. And that's it. Here is the aspect code:

public aspect LogAspect {

pointcut publicMethodExecuted(): execution(public * *(..));

after(): publicMethodExecuted() {
    System.out.printf("Enters on method: %s. \n", thisJoinPoint.getSignature());

    Object[] arguments = thisJoinPoint.getArgs();
    for (int i =0; i < arguments.length; i++){
        Object argument = arguments[i];
        if (argument != null){
            System.out.printf("With argument of type %s and value %s. \n", argument.getClass().toString(), argument);
        }
    }
    System.out.printf("Exits method: %s. \n", thisJoinPoint.getSignature());
}

For more complex examples I would recommend the book AspectJ: In Action.

Solution 2

@Loggable annotation and an AspectJ aspect from jcabi-aspects is a ready mechanism for you (I'm a developer):

@Loggable(Loggable.DEBUG)
public String load(URL url) {
  return url.openConnection().getContent();
}

To log both entry and exit, as per the question's requirements:

@Loggable(Loggable.DEBUG, prepend=true)
public String load(URL url) {
  return url.openConnection().getContent();
}

All logs go to SLF4J. Check this post for more details.

Solution 3

You can use different pointcuts to make your requirement. This documentation will help you.

Straight forward solution

Solution 4

You can try out this open source http://code.google.com/p/perfspy/. PerfSpy is a runtime logging, performance monitoring and code inspecting tool. It uses ApsectJ to weave around your application code at runtime, and logs the execution time of every method and its input parameters and values. It has a UI application, in which you can view the method invocations and their input and return values as trees. With it, you can spot performance bottlenecks and understand complex code flow.

Solution 5

Here is my simple implementation to log entering , exiting and log Exceptions from methods

Annotation

package test;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Documented
@Retention(RetentionPolicy.RUNTIME)
@Target({ ElementType.METHOD, ElementType.TYPE })
public @interface Audit {

}

Interceptor

import java.lang.reflect.Method;
import java.util.Arrays;
import java.util.logging.Level;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;


@Aspect
public class ExceptionInterceptor {

    private static final java.util.logging.Logger LOGGER = java.util.logging.Logger.getLogger(ExceptionInterceptor.class.getName());

    @Around("execution(* * (..))"
            + " && @annotation(test.Audit)"
    )
    public Object intercept(final ProceedingJoinPoint point) throws Throwable {
        final Method method
                = MethodSignature.class.cast(point.getSignature()).getMethod();
        String mName = method.getName();
        String cName = method.getDeclaringClass().getSimpleName();
        LOGGER.log(Level.INFO, "Entering {0}:{1}", new Object[]{cName, mName});
        Object out = null;
        try {
            out = point.proceed();
        } catch (Throwable t) {
            logExceptions(t, point);
        }
        LOGGER.log(Level.INFO, "Exiting {0}:{1}", new Object[]{cName, mName});
        return out;
    }

    private void logExceptions(Throwable t, final ProceedingJoinPoint point) {
        final Method method
                = MethodSignature.class.cast(point.getSignature()).getMethod();
        String mName = method.getName();
        String cName = method.getDeclaringClass().getSimpleName();
        Object[] params = point.getArgs();
        StringBuilder sb = new StringBuilder();
        sb.append("Exception caught for [");
        sb.append(cName);
        sb.append(".");
        sb.append(mName);
        for (int i = 0; i < params.length; i++) {
            Object param = params[i];

            sb.append("\n");
            sb.append("  [Arg=").append(i);
            if (param != null) {
                String type = param.getClass().getSimpleName();

                sb.append(", ").append(type);

                // Handle Object Array (Policy Override)
                if (param instanceof Object[]) {
                    sb.append("=").append(Arrays.toString((Object[]) param));
                } else {
                    sb.append("=").append(param.toString());
                }
            } else {
                sb.append(", null");
            }
            sb.append("]");
            sb.append("\n");
        }
        LOGGER.log(Level.SEVERE, sb.toString(), t);

    }
}

How to use it

@Audit  
public void testMethod(Int a,int b, String c){
}

Maven dependencies Compile

    <dependency>
        <groupId>org.aspectj</groupId>
        <artifactId>aspectjrt</artifactId>
        <version>1.8.7</version>
    </dependency> 

Weaving

        <plugin>
            <groupId>com.jcabi</groupId>
            <artifactId>jcabi-maven-plugin</artifactId>
            <executions>
                <execution>
                    <phase>compile</phase>
                    <goals>
                        <goal>ajc</goal>
                    </goals>
                </execution>
            </executions>
        </plugin> 

View more solutions