How to Use Aop with Aspectj for Logging

How to use AOP with AspectJ for logging?

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.

Logging Web application using Spring AOP and AspectJ

Your @AfterReturning declaration is incorrect, you forgot to specify the name of the argument containing the return value.

@AfterReturning(pointcut="execution(public * *(..))", returning="result")
public void logAfterReturning(JoinPoint joinPoint, Object result) {
...
}

issue with @Aspectj logging if @EnableTransactionManagement added in sprig boot project

Based on the error stack the issue is that the request instance is invalid. I would guess that the request instance autowired to the Aspect could be stale or rather not assosicated with the current thread. This means that request instance is not null and the check within logAround() method gives unexepected results.

RequestContextHolder.getRequestAttributes() would return null if no request attributes are currently bound to the thread. Modifying the

if (request ! = null) { ..} check with if (RequestContextHolder.getRequestAttributes() ! = null) {..} should fix the issue.

Also spring boot provides out of the box solutions to what you are currently attempting through AOP . Do check them out as well.

  • HTTP Tracing
  • Spring MVC Metrics

Spring AOP/AspectJ logging the execution time of a method but how to pass arguments to it? (Spring boot API)

This is very easy to do; I was a dum-dum when I originally posted this, but here's the answer for anyone looking to do the same:

When you create your interface that defines you annotation using Spring AOP/AspectJ, in your concrete class like I listed above, it has access to all the arguments passed to your method from the ProceedingJoinPoint object. So you can call getArgs() on this object to get all the arguments passed to the method in-question when its runs. It will return an Object[] so you will just need to have some conditional checks to cast it down to the type of your choice and make sure its not empty, so you don't get any exceptions at runtime. This is helpful if clients are POSTing to your API and you want to track the execution time of methods, but maybe you have hundreds/thousands of requests and need to specifically trace down exactly which calls follow which paths and what may be slowing your API down... so posting additional data from the requestBody maybe helpful in your logs...

e.g. I'll pretend I am tracking some method, that takes in a "Student" data type, which holds a bunch of data on a student (name, dob, gpa, etc...). This way, if I have different methods that query the Database with different SQL queries based on the requestBody the client POST to the API with, I can log this, to track down exactly which requests are slowing my API down and their flow within my codebase and which SQL queries they are calling. i.e.

@Aspect
@Component
@Slf4j
@ConditionalOnExpression("${aspect.enabled:true}")
public class ExecutionTimeAdvice {

@Around("@annotation(com.mailshine.springboot.aop.aspectj.advise.TrackExecutionTime)")
public Object executionTime(ProceedingJoinPoint point) throws Throwable {
MyCustomStudentType student; // Class to hold Student data
String studentName = "";
Object[] argsArray = point.getArgs();

if (argsArray.length > 0 && argsArray[0] instanceof MyCustomStudentType) {
student = (MyCustomStudentType) argsArray[0];
studentName = student.getName();
}

long startTime = System.currentTimeMillis();
Object object = point.proceed();
long endtime = System.currentTimeMillis();

// add the student name to your logs or any info you want to add with your
// execution time of your method, to make tracking your logs easier
log.info("Class Name: "+ point.getSignature().getDeclaringTypeName() +". Method Name: "+ point.getSignature().getName() + ". Time taken for Execution is : " + (endtime-startTime) +"ms" + ", for student name: " + studentName);

return object;
}
}

Placing log information inside a method: Using AspectJ , Spring

The short answer is: AOP is not meant to look into your methods because methods get refactored all the time and should be considered black boxes.

So neither Spring AOP nor AspectJ will do for you what you expect them to. The idea of AOP is to implement cross-cutting concerns. Logging is but one such concern. If you think you need intra-method logging, you can still do it manually. But if clean code means anything to you, you can just refactor your code to be more maintainable (and also more logging-friendly). Methods should be short, not have too many input parameters and not too much complexity.

So you can break up your complex spaghetti code method into a set of smaller methods or even extract new classes and use those from your method. I did this for your code (see below). Furthermore, returning 0 or -1 or whatever instead of throwing an exception is not OOP but C-style programming. So instead of logging problems based on return values, log them based on thrown exceptions and handle those exceptions (or let them escalate, if there is a fatal error) according to your application logic. My sample code also shows that.

Sample code, iteration 1

This example will work nicely with AspectJ because AspectJ is not based on delegating dynamic proxies and thus has no problems with self-invocation, e.g. internal method calls within a class.

package de.scrum_master.app;

public class UnexpectedResultException extends Exception {
private static final long serialVersionUID = 1L;

public UnexpectedResultException(String message) {
super(message);
}
}

As you can see, I have extracted a few methods from your complex one. In order to show you some more log output, I even added complexity into doSomething(..) again by calling the method doing complex stuff several times in a for-loop.

package de.scrum_master.app;

import java.util.Random;

public class Application {
public void doSomething(String name, Object someObj) {
int result = new Random().nextInt(100);
for (int counter = 0; counter < 5; counter++) {
try {
result = doComplexThing(result + 1);
} catch (UnexpectedResultException unexpectedResultException) {
result = 4;
}
}
result = doSomeMoreWork(result);
otherBusinessCode(result);
}

public int doComplexThing(int input) throws UnexpectedResultException {
if (input % 2 == 0)
throw new UnexpectedResultException("uh-oh");
return input % 5;
}

public int doSomeMoreWork(int input) {
return input * input;
}

public void otherBusinessCode(int input) {}

public static void main(String[] args) {
Application application = new Application();
application.doSomething("John Doe", new Integer(11));
}
}

The logging aspect could look like this:

package de.scrum_master.aspect;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
public class LoggingAspect {
@Pointcut("within (de.scrum_master.app..*) && execution(* *(..))")
private void loggingTargets() {}

@Before("loggingTargets()")
public void logEnterMethod(JoinPoint thisJoinPoint) {
System.out.println("ENTER " + thisJoinPoint);
}

@AfterReturning(pointcut = "loggingTargets()", returning = "result")
public void logExitMethod(JoinPoint thisJoinPoint, Object result) {
System.out.println("EXIT " + thisJoinPoint + " -> return value = " + result);
}

@AfterThrowing(pointcut = "loggingTargets()", throwing = "exception")
public void logException(JoinPoint thisJoinPoint, Exception exception) {
System.out.println("ERROR " + thisJoinPoint + " -> exception = " + exception);
}
}

The console log looks like this:

ENTER execution(void de.scrum_master.app.Application.main(String[]))
ENTER execution(void de.scrum_master.app.Application.doSomething(String, Object))
ENTER execution(int de.scrum_master.app.Application.doComplexThing(int))
ERROR execution(int de.scrum_master.app.Application.doComplexThing(int)) -> exception = de.scrum_master.app.UnexpectedResultException: uh-oh
ENTER execution(int de.scrum_master.app.Application.doComplexThing(int))
EXIT execution(int de.scrum_master.app.Application.doComplexThing(int)) -> return value = 0
ENTER execution(int de.scrum_master.app.Application.doComplexThing(int))
EXIT execution(int de.scrum_master.app.Application.doComplexThing(int)) -> return value = 1
ENTER execution(int de.scrum_master.app.Application.doComplexThing(int))
ERROR execution(int de.scrum_master.app.Application.doComplexThing(int)) -> exception = de.scrum_master.app.UnexpectedResultException: uh-oh
ENTER execution(int de.scrum_master.app.Application.doComplexThing(int))
EXIT execution(int de.scrum_master.app.Application.doComplexThing(int)) -> return value = 0
ENTER execution(int de.scrum_master.app.Application.doSomeMoreWork(int))
EXIT execution(int de.scrum_master.app.Application.doSomeMoreWork(int)) -> return value = 0
ENTER execution(void de.scrum_master.app.Application.otherBusinessCode(int))
EXIT execution(void de.scrum_master.app.Application.otherBusinessCode(int)) -> return value = null
EXIT execution(void de.scrum_master.app.Application.doSomething(String, Object)) -> return value = null
EXIT execution(void de.scrum_master.app.Application.main(String[])) -> return value = null

As you can see, you get all the logging you wanted to have in your initial question based on the new, more modular method structure. The old method becomes more readable and the new methods are simpler because they concentrate on doing the thing you extracted them for.

Please note: This sample code was run with AspectJ, not with the "AOP lite" framework Spring AOP. So in Spring AOP it would not work like this because:

  • Spring AOP cannot handle internal method calls (self-invocation), as I said above and is explained in the Spring manual.
  • Spring AOP also would not log static methods such as main because it only can intercept public, non-static interface methods (when using Java dynamic proxies) or additionally protected and package-scoped methods (when using CGLIB proxies).

So if you think about refactoring your code into what I suggested and also consider making some helper methods private but still want them logged, there is no other way than to configure Spring to use full AspectJ via LTW (load-time weaving) in order to use the full power of AOP.

Sample code, iteration 2

If you rather want to stick with Spring AOP and its proxies, but still need those internally called methods logged via AOP, you need to go one step further in your refactoring and extract the three new methods into an extra Spring component/bean which you wire into your application. Then the method calls would no longer be internal but go across component/bean boundaries and thus be intercepted by a Spring AOP logging aspect.

The Application worker methods class would be extracted and called like this:

package de.scrum_master.app;

// Make this into a @Component
public class MyWorker {
public int doComplexThing(int input) throws UnexpectedResultException {
if (input % 2 == 0)
throw new UnexpectedResultException("uh-oh");
return input % 5;
}

public int doSomeMoreWork(int input) {
return input * input;
}

public void otherBusinessCode(int input) {}
}
package de.scrum_master.app;

import java.util.Random;

public class Application {
// In a Spring context this would be injected via configuration
private MyWorker worker = new MyWorker();

public void doSomething(String name, Object someObj) {
int result = new Random().nextInt(100);
for (int counter = 0; counter < 5; counter++) {
try {
result = worker.doComplexThing(result + 1);
} catch (UnexpectedResultException unexpectedResultException) {
result = 4;
}
}
result = worker.doSomeMoreWork(result);
worker.otherBusinessCode(result);
}

public static void main(String[] args) {
Application application = new Application();
application.doSomething("John Doe", new Integer(11));
}
}

The aspect can stay unchanged.

The log output changes to something like this:

ENTER execution(void de.scrum_master.app.Application.main(String[]))
ENTER execution(void de.scrum_master.app.Application.doSomething(String, Object))
ENTER execution(int de.scrum_master.app.MyWorker.doComplexThing(int))
EXIT execution(int de.scrum_master.app.MyWorker.doComplexThing(int)) -> return value = 2
ENTER execution(int de.scrum_master.app.MyWorker.doComplexThing(int))
EXIT execution(int de.scrum_master.app.MyWorker.doComplexThing(int)) -> return value = 3
ENTER execution(int de.scrum_master.app.MyWorker.doComplexThing(int))
ERROR execution(int de.scrum_master.app.MyWorker.doComplexThing(int)) -> exception = de.scrum_master.app.UnexpectedResultException: uh-oh
ENTER execution(int de.scrum_master.app.MyWorker.doComplexThing(int))
EXIT execution(int de.scrum_master.app.MyWorker.doComplexThing(int)) -> return value = 0
ENTER execution(int de.scrum_master.app.MyWorker.doComplexThing(int))
EXIT execution(int de.scrum_master.app.MyWorker.doComplexThing(int)) -> return value = 1
ENTER execution(int de.scrum_master.app.MyWorker.doSomeMoreWork(int))
EXIT execution(int de.scrum_master.app.MyWorker.doSomeMoreWork(int)) -> return value = 1
ENTER execution(void de.scrum_master.app.MyWorker.otherBusinessCode(int))
EXIT execution(void de.scrum_master.app.MyWorker.otherBusinessCode(int)) -> return value = null
EXIT execution(void de.scrum_master.app.Application.doSomething(String, Object)) -> return value = null
EXIT execution(void de.scrum_master.app.Application.main(String[])) -> return value = null

exclusion of some fields/parameters from logging via Spring AOP

During runtime, a method parameter is just a value. The JVM does not know at this point if the caller called the method using constants, literals, fields or results of other method calls. That kind of information, you only see in the source code. In byte code, whatever dereferencing operation or computation necessary to determine the parameter's value (or a reference to the corresponding object) is done before calling the method. So there is no connection to the field annotation.

Would annotating method parameters be an alternative for you?

If your requirement is very specific, e.g. intercept field accesses from toString methods and return dummy values instead, if the field is annotated, that would be possible. But this would not be fool-proof. Imagine for example that toString calls a getter method instead of directly accessing the field or that a method other than toString logs the field. You do not always want to falisfy the field value on read access, because other parts of the application might rely on it working correctly. Not every toString call is made in order to log something.

I think you should solve the problem in another way, e.g. by applying filter rules for the logging tool you use. Or if you really want solve it at the application level, you could create an interface like

public interface PrivacyLogger {
String toStringSensitive();
}

and make each class containing sensitive information implement that interface. The logging aspect could then for each printed object determine if it is instanceof toStringSensitive(). If so, it would log the result of toStringSensitive() instead of toString(), i.e. in the simplest case something like

Object toBeLogged = whatever();
logger.log(
toBeLogged instanceof PrivacyLogger
? ((PrivacyLogger) toBeLogged).toStringSensitive()
: toBeLogged
);

Of course, you need to iterate over getArgs() and determine the correct log string for each object. Probably, you want to write a utility method doing that for the whole parameters array.

Moreover, in a complex class, the toStringSensitive() implementation should of course also check if its own fields are PrivacyLogger instances and in that case fold the values of their resapctive toStringSensitive() methods into itw own, so that it works recursively.

I am sorry I have no better news for you, but privacy is something which needs too be built into an application from the ground. There is no simple, fool-proof way to do that with one little aspect. The aspect can utilise the existing application infrastructure and avoid scattering and tangling, but it cannot decide on its own what needs to be prohibited from getting logged and what not.

how to implement logging with AOP Spring and log4j

Replace (in CRMLoggingAspect.java)

import java.util.logging.Logger;

with

import org.apache.log4j.Logger;



Related Topics



Leave a reply



Submit