Before we start a little hint: If you write @Around("logging()") your pointcut method should be renamed from loggingResponseTime() to actually logging(), otherwise the aspect will not work.
Now as for your real problem: You are making a typical beginners' mistake by advising code too broadly, i.e. you are intercepting all method executions (outside the JDK). If you use Eclipse and AJDT and you put your cursor into the tracing() advice you will see something like this in the AspectJ "cross reference" window using your current pointcut:
You can immediately see your problem: Your pointcut captures code in your anonymous ThreadLocal subclass. This leads to endless recursion and finally to the StackOverflowError as you can see in your own callstack if you inspect it.
Now here is some sample code demonstrating the problem for other people's reference:
Driver application:
package de.scrum_master.app;
public class Application {
public static void main(String[] args) {
System.out.println(bar(foo()));
}
public static String bar(String text) {
return text + "bar";
}
private static String foo() {
return "foo";
}
}
Aspect:
package de.scrum_master.aspect;
import java.util.UUID;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
@Aspect
public class DemoAspect {
private static ThreadLocal<String> id = new ThreadLocal<String>() {
@Override
protected String initialValue() {
return UUID.randomUUID().toString();
}
};
@Pointcut("execution(* *(..))")
public void logging() {}
@Around("logging()")
public Object tracing(ProceedingJoinPoint thisJoinPoint) throws Throwable {
String methodSignature = thisJoinPoint.getSignature().toString();
if (id.get().toString() == null || id.get().toString().length() == 0)
id.set(UUID.randomUUID().toString());
System.out.println("Entering into " + methodSignature);
Object ret = thisJoinPoint.proceed();
System.out.println(id.get().toString());
System.out.println("Exiting from " + methodSignature);
id.remove();
return ret;
}
}
Console output:
Exception in thread "main" java.lang.StackOverflowError
at org.aspectj.runtime.reflect.SignatureImpl$CacheImpl.get(SignatureImpl.java:217)
at org.aspectj.runtime.reflect.SignatureImpl.toString(SignatureImpl.java:50)
at org.aspectj.runtime.reflect.SignatureImpl.toString(SignatureImpl.java:62)
at de.scrum_master.aspect.DemoAspect$1.initialValue_aroundBody1$advice(DemoAspect.aj:29)
at de.scrum_master.aspect.DemoAspect$1.initialValue(DemoAspect.aj:1)
at de.scrum_master.aspect.DemoAspect$1.initialValue(DemoAspect.aj:1)
at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:160)
at java.lang.ThreadLocal.get(ThreadLocal.java:150)
at de.scrum_master.aspect.DemoAspect$1.initialValue_aroundBody1$advice(DemoAspect.aj:30)
at de.scrum_master.aspect.DemoAspect$1.initialValue(DemoAspect.aj:1)
at de.scrum_master.aspect.DemoAspect$1.initialValue(DemoAspect.aj:1)
at java.lang.ThreadLocal.setInitialValue(ThreadLocal.java:160)
at java.lang.ThreadLocal.get(ThreadLocal.java:150)
(...)
So what can you do? It is actually quite simple: Just exclude the joinpoints you do not really want to intercept from your pointcut. For that you have several options. I am just naming a few:
A) Put your aspects into a specific package and exclude all (aspect) classes in that package:
@Pointcut("execution(* *(..)) && !within(de.scrum_master.aspect..*)")
B) Exclude all classes annotated by @Aspect:
@Pointcut("execution(* *(..)) && !within(@org.aspectj.lang.annotation.Aspect *)")
C) Exclude all (aspect) classes matching a certain naming scheme like *Aspect:
@Pointcut("execution(* *(..)) && !within(*..*Aspect)")
D) Exclude code from all ThreadLocal subclasses (+ syntax):
@Pointcut("execution(* *(..)) && !within(ThreadLocal+)")
In each case the result will be the same:
Entering into void de.scrum_master.app.Application.main(String[])
Entering into String de.scrum_master.app.Application.foo()
d2b83f5f-7282-4c06-9b81-6601c8e0499d
Exiting from String de.scrum_master.app.Application.foo()
Entering into String de.scrum_master.app.Application.bar(String)
0d1c9463-4bbd-427d-9d64-c7f3967756cf
Exiting from String de.scrum_master.app.Application.bar(String)
foobar
aa96bbbd-a1a1-450f-ae6e-77ab204c5fb2
Exiting from void de.scrum_master.app.Application.main(String[])
By the way: I have strong doubts about your usage of UUIDs because I see no value in creating expensive objects here. How about just logging timestamps? Why do you need globally unique IDs for logging? They tell you nothing. Furthermore, not only are you creating one ID per thread, but if you use the uncommented id.remove() you even create one per call! Sorry, but this is bloat, it slows down your code and creates lots of unnecessary objects. I do not think this is wise.
Update:
I forgot to explain the reason for the endless recursion: Your advice calls ThreadLocal.get(), assuming it could be null. Actually it cannot be because if the value has not been initialised, get() does so by utilising initialValue(). Even if you manually call remove(), the next time you call get() it will again initialise the value again and so forth. This is documented behaviour:
Returns the value in the current thread's copy of this thread-local variable. If the variable has no value for the current thread, it is first initialized to the value returned by an invocation of the initialValue() method.
So what happens, step by step?
- A method is called.
- Your around advice kicks in.
- You call
id.get() from the advice.
ThreadLocal.get() checks if a value is set, notices that there is none and calls your overridden initialValue() method.- Because the overridden
initialValue() method is captured by your match-all pointcut execution(* *(..)), again your advice kicks in before the initial value has been set. The end result is that the loop starts again and so forth - endless recursion, quod erat demonstrandum.
So actually your problem boils down to calling get() on an uninitialised ThreadLocal subclass from an advice while simultaneously targetting its user-defined initialValue() method with the same advice. This is what creates the endless recursion and ultimately makes your stack overflow.
My recommendation is to exclude your aspect from the pointcut, see example pointcuts above. You should also get rid of the null check for the ThreadLocal value because it is superfluous. Last but not least, I assume you want one ThreadLocal value per thread and not one per method call. So you can do without any set() or remove() calls altogether.
Modified driver class, creating an additional thread:
package de.scrum_master.app;
public class Application {
public static void main(String[] args) throws InterruptedException {
new Thread(new Runnable() {
@Override
public void run() {
System.out.println(bar(foo()));
}
}).start();
Thread.sleep(200);
}
public static String bar(String text) {
return text + "bar";
}
private static String foo() {
return "foo";
}
}
Improved aspect:
package de.scrum_master.aspect;
import java.util.UUID;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
@Aspect
public class DemoAspect {
private static ThreadLocal<UUID> id = new ThreadLocal<UUID>() {
@Override
protected UUID initialValue() {
return UUID.randomUUID();
}
};
@Pointcut("execution(* *(..)) && !within(DemoAspect)")
public void logging() {}
@Around("logging()")
public Object tracing(ProceedingJoinPoint thisJoinPoint) throws Throwable {
Signature methodSignature = thisJoinPoint.getSignature();
System.out.println(
"Thread " + Thread.currentThread().getId() +
"[" + id.get() +
"] >>> " + methodSignature
);
Object result = thisJoinPoint.proceed();
System.out.println(
"Thread " + Thread.currentThread().getId() +
"[" + id.get() +
"] <<< " + methodSignature
);
return result;
}
}
Console output:
Thread 1[549d0856-0a92-4031-9331-a1317d6a43c4] >>> void de.scrum_master.app.Application.main(String[])
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] >>> void de.scrum_master.app.Application.1.run()
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] >>> String de.scrum_master.app.Application.access$0()
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] >>> String de.scrum_master.app.Application.foo()
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] <<< String de.scrum_master.app.Application.foo()
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] <<< String de.scrum_master.app.Application.access$0()
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] >>> String de.scrum_master.app.Application.bar(String)
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] <<< String de.scrum_master.app.Application.bar(String)
foobar
Thread 9[32c8444c-0f1f-4023-9b97-69d5beda3b4c] <<< void de.scrum_master.app.Application.1.run()
Thread 1[549d0856-0a92-4031-9331-a1317d6a43c4] <<< void de.scrum_master.app.Application.main(String[])
As you can see, threads already have unique IDs, so maybe you want consider implementing your aspect without any UUIDs altogether.
