Intermittent "Advice precedence circularity error" using Spring AOP

Question

I'm using Spring AOP to add some performance instrumentation on my code. And I have a unit test to test that the advices are triggered. The test works locally but fails intermittently in Jenkins CI job with "Advice precedence circularity error"

java.lang.IllegalStateException: Failed to load ApplicationContext
at org.springframework.test.context.TestContext.getApplicationContext(TestContext.java:157)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:109)
at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:75)
at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:321)
at org.springframework.test.context.testng.AbstractTestNGSpringContextTests.springTestContextPrepareTestInstance(AbstractTestNGSpringContextTests.java:133)
...
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'testTrackingUrlDao' defined in file [***/build/classes/java/test/com/example/analytics/aspect/TestTrackingUrlDao.class]: Initialization of bean failed; nested exception is java.lang.IllegalArgumentException: Advice precedence circularity error
...
Caused by: java.lang.IllegalArgumentException: Advice precedence circularity error
at org.springframework.aop.aspectj.autoproxy.AspectJAwareAdvisorAutoProxyCreator.sortAdvisors(AspectJAwareAdvisorAutoProxyCreator.java:82)
at org.springframework.aop.framework.autoproxy.AbstractAdvisorAutoProxyCreator.findEligibleAdvisors(AbstractAdvisorAutoProxyCreator.java:90)
at org.springframework.aop.framework.autoproxy.AbstractAdvisorAutoProxyCreator.getAdvicesAndAdvisorsForBean(AbstractAdvisorAutoProxyCreator.java:68)
at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.wrapIfNecessary(AbstractAutoProxyCreator.java:359)
at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.postProcessAfterInitialization(AbstractAutoProxyCreator.java:322)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsAfterInitialization(AbstractAutowireCapableBeanFactory.java:407)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1461)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
... 66 more

I have around, afterThrowing and after pointcuts with the same regular expression. Initially I didn't set the order explicitly on the advices and the Spring context initialization failed intermittently for the real code, not just the unit test. After reading this link, I rearranged my advices in "around" followed by "afterThrowing" followed by "after" order and added explicit order using the Order annotation. And the code works fine now in production. But the unit test is failing intermittently (sometimes passes, sometimes fails) in our Jenkins CI job. I read somewhere it says different jdk version might be causing the problem. I'm not sure what exactly that means and how to fix that. I'm still on Spring version 3.1.x due to legacy issue, btw.

Here's the Aspect code:

@Aspect
@Component
public class AnalyticsAspect {

    @Order(1)
    @Around("execution(* com.example.analytics.dao.*.find*(..)) || execution(* com.example.analytics.dao.*.get*(..))")
    public Object updateReadCounterTimer(ProceedingJoinPoint joinPoint) throws Throwable {
        LOGGER.info("updateReadCounterTimer");
        long currTime = System.currentTimeMillis();
        Object retVal = joinPoint.proceed();
        readCounter.stopWatch.start(currTime);
        readCounter.stopWatch.stop();
        LOGGER.info("updateReadCounterTimer done");
        return retVal;
    }

    @Order(2)
    @Around("execution(* com.example.analytics.dao.*.save*(..)) || execution(* com.example.analytics.dao.*.set*(..))")
    public Object updateWriteCounterTimer(ProceedingJoinPoint joinPoint) throws Throwable {
        LOGGER.info("updateWriteCounterTimer");
        long currTime = System.currentTimeMillis();
        Object retVal = joinPoint.proceed();
        writeCounter.stopWatch.start(currTime);
        writeCounter.stopWatch.stop();
        LOGGER.info("updateWriteCounterTimer done");
        return retVal;
    }

    /**
    * This is called whenever there's an exception thrown from the matching DAO methods
    */
    @Order(3)
    @AfterThrowing(pointcut = "execution(* com.example.alytics.dao.*.find*(..)) || execution(* com.example.analytics.dao.*.get*(..))",
                throwing = "error")
    public void updateErrorReadCounter(JoinPoint jointPoint, Throwable error) {
        LOGGER.info("updateErrorReadCounter");
        readCounter.failureCounter.increment();
        LOGGER.info("updateErrorReadCounter done");
    }

    @Order(4)
    @AfterThrowing("execution(* com.example.alytics.dao.*.save*(..)) || execution(* com.example.analytics.dao.*.set*(..))")
    public void updateErrorWriteCounter(JoinPoint jointPoint) {
        LOGGER.info("updateErrorWriteCounter");
        writeCounter.failureCounter.increment();
        LOGGER.info("updateErrorWriteCounter done");
    }

    /**
    * NOTE assumption is that all reader method names will have the "find***" or "get***" pattern
    */
    @Order(5)
    @After("execution(* com.example.alytics.dao.*.find*(..)) || execution(* com.example.analytics.dao.*.get*(..))")
    public void updateSuccessReadCounter(JoinPoint jointPoint) {
        LOGGER.info("updateSuccessReadCounter");
        readCounter.successCounter.increment();
        LOGGER.info("updateSuccessReadCounter done");
    }

    /**
    * NOTE assumption is that all writer method names will have the "save***" or "set***" pattern
    */
    @Order(6)
    @After("execution(* com.example.analytics.dao.*.save*(..)) || execution(* com.example.analytics.dao.*.set*(..))")
    public void updateSuccessWriteCounter(JoinPoint jointPoint) {
        LOGGER.info("updateSuccessWriteCounter");
        writeCounter.successCounter.increment();
        LOGGER.info("updateSuccessWriteCounter done");
    }

}

Here are some snippets from the unit test class:

@ContextConfiguration(locations = { "classpath:applicationContext-test.xml" })
public class AnalyticsAspectTest extends AbstractTestNGSpringContextTests {

    @Autowired
    @Qualifier("testTrackingUrlDao")
    TrackingUrlDao trackingUrlDao;

    @Autowired
    @Qualifier("testAnalyticEventDao")
    AnalyticEventDao analyticEventDao;

    @Autowired
    AnalyticsAspect analyticsAspect;

    @Test
    public void testReadSuccessCounterOnTrackingUrlDaoFindById() {
        List<TrackingUrl> trackingUrls = trackingUrlDao.findById("abc");
        assertEquals(analyticsAspect.readCounter.successCounter.getValue(), 1);
        assertEquals(trackingUrls.size(), 1);
    }
    ...
}

/**
* This is a dummy implementation of AnalyticEventDao interface so that we can autowire it
* into the VideoAnalyticsAspectTest class 
*/
@Component
class TestAnalyticEventDao implements AnalyticEventDao {

    @Override
    public List<AnalyticEvent> findById(String id) {
    ...
    }

    @Override
    public void save(AnalyticEvent event) {
    ...
    }
}

/**
* This is a dummy implementation of TrackingUrlDao interface so that we can autowire it
* into the AnalyticsAspectTest class 
*/
@Component
class TestTrackingUrlDao implements TrackingUrlDao {
    // set it to true to simulate exception when DAO method is called
    private boolean testFailure = false;

    @Override
    public List<TrackingUrl> findById(String id) {
...
    }

    @Override
    public void save(TrackingUrl trackingUrl) {
...
    }

}

Answer 1

Why don't you avoid the circularity problem by merging the three advices per operation (read/write) into just one each? Besides, you have a few problems in your code:

• You start your stopwatch after the proceed(), i.e. you are timing nothing. I fixed that.
• You never stop the stopwatch in case of an error. I fixed that by moving it into a finally block.
• I also think you are logging too much. Is it really necessary to log the stopwatch and counter actions before and after each one? And the log output looks really cryptic. I removed logging before counter update because the logging as such would take longer than the increment action. I am only logging after counter update. I kept the logging before and after the stopwatch, though, so as not to change too much.

@Aspect
@Component
public class AnalyticsAspect {
  private static final Log LOGGER = new Log4JLogger();
  private StatisticsCollector readCounter;
  private StatisticsCollector writeCounter;

  @Around("execution(* com.example.analytics.dao.*.find*(..)) || execution(* com.example.analytics.dao.*.get*(..))")
  public Object readTimerAndCounter(ProceedingJoinPoint joinPoint) throws Throwable {
    Object retVal = null;
    LOGGER.info("Read timer - start");
    readCounter.stopWatch.start(System.currentTimeMillis());
    try {
      retVal = joinPoint.proceed();
    }
    catch (Exception e) {
      readCounter.failureCounter.increment();
      LOGGER.info("Read error - counter updated");
      throw e;
    }
    finally {
      readCounter.stopWatch.stop();
      LOGGER.info("Read timer - stop");
    }
    readCounter.successCounter.increment();
    LOGGER.info("Read success - counter updated");
    return retVal;
  }

  @Around("execution(* com.example.analytics.dao.*.save*(..)) || execution(* com.example.analytics.dao.*.set*(..))")
  public Object writeTimerAndCounter(ProceedingJoinPoint joinPoint) throws Throwable {
    Object retVal;
    LOGGER.info("Write timer - start");
    writeCounter.stopWatch.start(System.currentTimeMillis());
    try {
      retVal = joinPoint.proceed();
    }
    catch (Exception e) {
      writeCounter.failureCounter.increment();
      LOGGER.info("Write error - counter updated");
      throw e;
    }
    finally {
      writeCounter.stopWatch.stop();
      LOGGER.info("Write timer - stop");
    }
    writeCounter.successCounter.increment();
    LOGGER.info("Write success - counter updated");
    return retVal;
  }
}

Try if that works better. Of course I could not test it because you did not share any application code.