Search code examples
javaaopaspectj

AspectJ - Pointcut with if() expression causes infinite recursion

I'm trying to write an aspect, which will intercept all method calls if system property has some specific value. However I don't need any method from advice control flow to be intercepted.

I'm using !cflow(adviceexecution()) expression to achieve this, but it doesn't seem to work in conjunction with if() expression. As a result I'm getting StackOverflowError because of infinite recursion.

Aspect code:

@Aspect
public class SomeAspect {

    @Pointcut("execution(* *.*(..)) && if()")
    public static boolean allMethodCalls() {
        return PropertyReader.hasSpecificProperty();
    }

    @Pointcut("cflow(adviceexecution())")
    public void aspectCalls() {
    }

    @Before("allMethodCalls() && !aspectCalls()")
    public void logSomething() {
        // logging behavior
    }
}

PropertyReader code:

public class PropertyReader {
    public static boolean hasSpecificProperty() {
        return System.getProperty("specificProperty") != null;
    }
}
Solution

  • adviceexecution() will not match because your dynamic if() pointcut gets evaluated before the advice gets executed. After all, that is what if() is all about: to decide if an advice should be executed or not.

    Let us say, the situation is like this:

    package de.scrum_master.app;

public class PropertyReader {
  public static boolean hasSpecificProperty() {
    return System.getProperty("specificProperty") != null;
  }

  public void doSomething(String info) {
    System.out.println("Doing something " + info);
    hasSpecificProperty();
  }

  public static void main(String[] args) {
    System.clearProperty("specificProperty");
    new PropertyReader().doSomething("with inactive property");
    System.setProperty("specificProperty", "true");
    new PropertyReader().doSomething("with active property");
    System.clearProperty("specificProperty");
  }
}

    Now the simplest solution would be to pull the hasSpecificProperty() logic right into the aspect itself because it is trivial. You can either define a local static method or just inline it into the if() pointcut:

    package de.scrum_master.app;

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

@Aspect
public class SomeAspect {
  @Pointcut("execution(* *(..)) && if()")
  public static boolean allMethodCalls() {
    return System.getProperty("specificProperty") != null;
  }

  @Pointcut("cflow(adviceexecution())")
  public void aspectCalls() {}

  @Before("allMethodCalls() && !aspectCalls()")
  public void logSomething(JoinPoint thisJoinPoint) {
    System.out.println(thisJoinPoint);
    PropertyReader.hasSpecificProperty();
  }
}

    This will yield the following console log:

    Doing something with inactive property
execution(void de.scrum_master.app.PropertyReader.doSomething(String))
Doing something with active property
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())

    As you can see, there is no problem in calling hasSpecificProperty() from the application or even from the aspect's advice because in the one problematic place there is it is inlined.

    If you want to avoid inlining or copying the method into the aspect, you need to do manual bookkeeping within the aspect, I am afraid:

    package de.scrum_master.app;

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

@Aspect
public class SomeAspect {
  private static ThreadLocal<Boolean> isInPointcut = new ThreadLocal<Boolean>() {
    @Override protected Boolean initialValue() { return false; }
  };

  @Pointcut("execution(* *(..)) && if()")
  public static boolean allMethodCalls() {
    if (isInPointcut.get())
      return false;
    isInPointcut.set(true);
    boolean result = PropertyReader.hasSpecificProperty();
    isInPointcut.set(false);
    return result;
  }

  @Pointcut("cflow(adviceexecution()) || within(SomeAspect)")
  public void aspectCalls() {}

  @Before("allMethodCalls() && !aspectCalls()")
  public void logSomething(JoinPoint thisJoinPoint) {
    System.out.println(thisJoinPoint);
    PropertyReader.hasSpecificProperty();
  }
}

    The console log is identical. Please note that || within(SomeAspect) is necessary so as to avoid capturing the anonymous ThreadLocal class.

    Update: This follow-up question was just asked:

    I don't quite understand why do we need ThreadLocal instead of simple boolean flag. Could you please explain?

    The short answer is: in order to make the aspect thread-safe. If several threads read and write the static member isInPointcut concurrently

    • either you need to synchronise access, making this a performance bottleneck because all threads would have to wait for the aspect to perform its many dynamic checks,
    • or you use a ThreadLocal variable, providing an independent instance of the flag to each thread, thus enabling the threads to proceed concurrently.

    If you do neither, your aspect will break, reading wrong values of the flag set by other threads. I will demonstrate it to you. Let's change the demo application as follows:

    package de.scrum_master.app;

import java.util.ArrayList;
import java.util.List;
import java.util.Random;

public class PropertyReader {
  private static int callCounter = 0;
  private static final Random RANDOM = new Random();

  public static boolean hasSpecificProperty() {
    synchronized (RANDOM) {
      callCounter++;
    }
    try {
      Thread.sleep(25);
    } catch (InterruptedException e) {
      e.printStackTrace();
    }
    return System.getProperty("specificProperty") != null;
  }

  public void doSomething(String info) {
    System.out.println("Doing something " + info);
    hasSpecificProperty();
  }

  public static int doStuff(final int numThreads, final boolean specificPropertyState) throws InterruptedException {
    if (specificPropertyState)
      System.setProperty("specificProperty", "true");
    else
      System.clearProperty("specificProperty");

    List<Thread> threads = new ArrayList<>();
    long startTime = System.currentTimeMillis();
    callCounter = 0;

    for (int i = 0; i < numThreads; i++) {
      Thread newThread = new Thread(() -> {
        new PropertyReader().doSomething("with active property");
      });
      threads.add(newThread);
      newThread.start();
    }

    for (Thread thread : threads)
      thread.join();

    System.clearProperty("specificProperty");
    System.out.println("Call counter = " + callCounter);
    System.out.println("Duration = " + (System.currentTimeMillis() - startTime) + " ms");
    return callCounter;
  }

  public static void main(String[] args) throws InterruptedException {
    final int NUM_THREADS = 10;
    int callCounterInactiveProperty = doStuff(NUM_THREADS, false);
    int callCounterActiveProperty = doStuff(NUM_THREADS, true);
    int callCounterDelta = callCounterActiveProperty - callCounterInactiveProperty;
    if (callCounterDelta != 3 * NUM_THREADS)
      throw new RuntimeException("Call counter delta should be " + 3 * NUM_THREADS + ", not " + callCounterDelta);
  }
}

    You may need a while to understand this code. Basically I do the following:

    • Introduce a new member static int callCounter the purpose of which is that method static boolean hasSpecificProperty() can use it to count how often it was called.
    • Introduce some helper object static final Random RANDOM (could also be any other object type) to synchronise callCounter upon because we cannot synchronise on callCounter itself, even if we make it an Integer instead of an int, because when incrementing the counter we would always have to create a new Integer instance different from the one synchronised upon. I tried, sometimes it counts wrong. Trust me, I tried.
    • Make hasSpecificProperty() slower by adding a Thread.sleep(25) to it, provoking concurrency problems. You said by yourself that your version of that method is more complex than the one you showed in your question.
    • Introduce a new method static int doStuff(final int numThreads, final boolean specificPropertyState) which creates a user-defined number of threads and runs them concurrently with system property specificProperty either set or unset depending on how the user calls doStuff(..). The method then waits until all threads are finished, prints the duration and returns the current value of callCounter. If the aspect works correctly this return value should always be the same for the same method parameters.
    • main(..) now calls doStuff(..) twice, first with inactive system property, then with active one. There should be a difference (delta) between both variants because hasSpecificProperty() gets executed more often if the property is active because from within the aspect advice logSomething(..) it gets called and this advice will only be executed if the system property is active as determined by the if() pointcut.

    Now if we run the program the console log says (shortened a bit):

    Doing something with active property
Doing something with active property
(...)
Doing something with active property
Doing something with active property
Call counter = 40
Duration = 151 ms
execution(void de.scrum_master.app.PropertyReader.lambda$0())
execution(void de.scrum_master.app.PropertyReader.lambda$0())
(...)
execution(void de.scrum_master.app.PropertyReader.lambda$0())
execution(void de.scrum_master.app.PropertyReader.lambda$0())
execution(void de.scrum_master.app.PropertyReader.doSomething(String))
execution(void de.scrum_master.app.PropertyReader.doSomething(String))
(...)
execution(void de.scrum_master.app.PropertyReader.doSomething(String))
execution(void de.scrum_master.app.PropertyReader.doSomething(String))
Doing something with active property
Doing something with active property
(...)
Doing something with active property
Doing something with active property
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())
(...)
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())
Call counter = 70
Duration = 180 ms

    The call counters always differ by 3 * NUM_THREADS because with active system property three method executions will be intercepted per thread, thus the advice runs 3 times and calls hasSpecificProperty() each time as well.

    Now if we "simplify" (thus break) the aspect like this:

    package de.scrum_master.app;

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

@Aspect
public class SomeAspect {
  private static boolean isInPointcut = false;

  @Pointcut("execution(* *(..)) && if()")
  public static boolean allMethodCalls() {
    if (isInPointcut)
      return false;
    isInPointcut = true;
    boolean result = PropertyReader.hasSpecificProperty();
    isInPointcut = false;
    return result;
  }

  @Pointcut("cflow(adviceexecution()) || within(SomeAspect)")
  public void aspectCalls() {}

  @Before("allMethodCalls() && !aspectCalls()")
  public void logSomething(JoinPoint thisJoinPoint) {
    System.out.println(thisJoinPoint);
    PropertyReader.hasSpecificProperty();
  }
}

    The console log changes to:

    Doing something with active property
Doing something with active property
(...)
Doing something with active property
Doing something with active property
Call counter = 13
Duration = 161 ms
Doing something with active property
Doing something with active property
(...)
execution(void de.scrum_master.app.PropertyReader.lambda$0())
execution(void de.scrum_master.app.PropertyReader.doSomething(String))
Doing something with active property
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())
Call counter = 16
Duration = 190 ms
Exception in thread "main" java.lang.RuntimeException: Call counter delta should be 30, not 3
    at de.scrum_master.app.PropertyReader.main(PropertyReader.java:61)

    Uh-oh! The count differs in an unexpected way and you also see that the advice runs only once, afterwards the flag's state is messed up. So your logging, tracing or whatever else the aspect is supposed to do would fail.

    Now we could quickly fix that by making the if() pointcut method synchronized:

    public static synchronized boolean allMethodCalls(JoinPoint thisJoinPoint)

    This works, but the runtime for each call of doStuff(..) increases from ~190 ms to ~800 ms, i.e. 4 times slower than before:

    Doing something with active property
(...)
Doing something with active property
Call counter = 40
Duration = 821 ms
execution(void de.scrum_master.app.PropertyReader.lambda$0())
(...)
execution(boolean de.scrum_master.app.PropertyReader.hasSpecificProperty())
Call counter = 70
Duration = 802 ms

    Try for yourself if you like. Now after this long explanation I think you agree that a ThreadLocal is better than a simple boolean even if the latter can be made to work by synchronising the pointcut method. But only boolean without synchronisation would break the aspect, making it thread-unsafe.