CODEWITHSUNDEEP
javaspringspring-bootspring-aopspring-retry
user2769790
user2769790

Reputation: 193

@Recover method not intercepted by Spring AOP advice

While writing code using Spring/Java and Aspect oriented programing, I'm facing an issue. In the service class, I have the retry method using @Retryable and a recovery method using @Recover.

Each of these 2 methods are attached to Aspects. The Retryable method - "triggerJob" inside TestProcessService is attached to these methods in TestAspect class - beforeTestTriggerJobsAdvice, afterTestTriggerJobsAdvice, onErrorTestTriggerJobsAdvice. They all are working fine and getting triggered at the right time.

PROBLEM STATEMENT: The Recovery method - "recover" inside TestProcessService is attached to these methods in TestAspect class - beforeRecoveryTestJobsAdvice, onErrorRecoveryTestTriggerJobsAdvice, and afterRecoveryTestTriggerJobsAdvice.

BUT NONE OF THESE ASPECT METHODS ARE GETTING CALLED once the code reached the recover method inside TestProcessService.

Here is the code:

SCHEDULER CLASS (triggers the methods inside TEST_MyProcessService class at regular interval)

@Slf4j
@Component
public class TEST_ScheduledProcessPoller {

    private final TEST_MyProcessService MyProcessService;
    private final MyServicesConfiguration MyServicesConfiguration;

    public TEST_ScheduledProcessPoller(TEST_MyProcessService MyProcessService,
                                  MyServicesConfiguration MyServicesConfiguration) {
        this.MyProcessService = MyProcessService;
        this.MyServicesConfiguration = MyServicesConfiguration;
    }

    @Scheduled(cron = "0 0/2 * * * *")
    public void scheduleTaskWithFixedDelay() {
        try {
            log.info("scheduleTaskWithFixedDelay");
            this.triggerMyJobs(true);
        } catch (Exception e) {
            log.error(e.getMessage());
        }
    }

    protected void triggerMyJobs(boolean isDaily) throws Exception {
        log.info("triggerMyJobs");
        MyServiceType serviceType = this.MyServicesConfiguration.getMy();
        this.MyProcessService.triggerJob(serviceType, isDaily, 1L);
    }
}

SERVICE CLASS:

@Slf4j
@Service
public class TEST_MyProcessService {

    @Retryable(maxAttemptsExpression = "${api.retry.limit}", backoff = @Backoff(delayExpression = "${api.retry.max-interval}"))
    public void triggerJob(MyServiceType MyServiceType, boolean isDaily, long eventId) {
        // Some code here that can throw exceptions.
        log.info("triggerJob");
        throw new RuntimeException("triggerJob");
    }

    @Recover
    public void recover(MyServiceType MyServiceType, boolean isDaily, long eventId) {
        log.info("recover");
        // Some code here that can throw exceptions.
        throw new RuntimeException();
    }
}

ASPECT CLASS:

@Component
@Slf4j
public class TEST_MyAspect {

    @Pointcut("execution(* packgName.otherProj.services.TEST_MyProcessService.triggerJob(..))")
    public void MyTriggerJobs() {
    }

    @Pointcut("execution(* packgName.otherProj.services.TEST_MyProcessService.recover(..))")
    public void MyRecoverJobs() {
    }

    @Before("MyTriggerJobs()")
    public void beforeMyTriggerJobsAdvice(JoinPoint joinPoint) {
        log.info("log beforeMyTriggerJobsAdvice");
    }

    @AfterReturning("MyTriggerJobs()")
    public void afterMyTriggerJobsAdvice(JoinPoint joinPoint) {
        log.info("log afterMyTriggerJobsAdvice");
    }

    @AfterThrowing(value = "MyTriggerJobs()", throwing = "error")
    public void onErrorMyTriggerJobsAdvice(JoinPoint joinPoint, Throwable error) {
        log.info("log onErrorMyTriggerJobsAdvice");
    }

    @Before("MyRecoverJobs()")
    public void beforeMyRecoverJobsAdvice(JoinPoint joinPoint) {
        log.info("log beforeMyRecoverJobsAdvice");
    }

    @AfterThrowing(value = "MyRecoverJobs()", throwing = "error")
    public void onErrorRecoveryMyTriggerJobsAdvice(JoinPoint joinPoint, Throwable error) {
        log.info("log onErrorRecoveryMyTriggerJobsAdvice");
    }


    @AfterReturning("MyRecoverJobs()")
    public void afterRecoveryMyTriggerJobsAdvice(JoinPoint joinPoint) {
        log.info("log afterRecoveryMyTriggerJobsAdvice");
    }
}

LOG output:

2021-06-02 20:56:00.016  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.c.TEST_ScheduledProcessPoller    : scheduleTaskWithFixedDelay
2021-06-02 20:56:00.016  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.c.TEST_ScheduledProcessPoller    : triggerBdaJobs
2021-06-02 20:56:00.051  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.component.aspect.TEST_BdaAspect  : log beforeBdaTriggerJobsAdvice
2021-06-02 20:56:00.060  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.services.TEST_BdaProcessService  : triggerJob
2021-06-02 20:56:00.061  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.component.aspect.TEST_BdaAspect  : log onErrorBdaTriggerJobsAdvice
2021-06-02 20:56:05.065  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.component.aspect.TEST_BdaAspect  : log beforeBdaTriggerJobsAdvice
2021-06-02 20:56:05.066  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.services.TEST_BdaProcessService  : triggerJob
2021-06-02 20:56:05.066  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.component.aspect.TEST_BdaAspect  : log onErrorBdaTriggerJobsAdvice
2021-06-02 20:56:10.070  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.component.aspect.TEST_BdaAspect  : log beforeBdaTriggerJobsAdvice
2021-06-02 20:56:10.070  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.services.TEST_BdaProcessService  : triggerJob
2021-06-02 20:56:10.070  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.component.aspect.TEST_BdaAspect  : log onErrorBdaTriggerJobsAdvice
2021-06-02 20:56:10.070  INFO [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.services.TEST_BdaProcessService  : recover
2021-06-02 20:56:10.070 ERROR [,60b7f0602b2ecb0deefc04d6840b6274,eefc04d6840b6274,true] 92605 --- [   scheduling-1] c.c.p.r.c.TEST_ScheduledProcessPoller    : null

Upvotes: 1

Views: 1179

Answers (1)

kriegaex
kriegaex

Reputation: 67457

I am not a Spring user, but interested in all things AOP, both AspectJ and Spring AOP. I liked your little puzzle. Thanks to your MCVE, I was able to reproduce the issue and debug into it. This is a perfect example for why an MCVE is so much superior to simply posting a bunch of code snippets. So thanks for that, please keep up this way of asking questions.

When looking at the situation in a debugger, you see that while the aspect is proceeding into triggerJob, at some point we are in method AnnotationAwareRetryOperationsInterceptor.invoke and there we have the following code:

@Override
public Object invoke(MethodInvocation invocation) throws Throwable {
    MethodInterceptor delegate = getDelegate(invocation.getThis(), invocation.getMethod());
    if (delegate != null) {
        return delegate.invoke(invocation);
    }
    else {
        return invocation.proceed();
    }
}

At this point Spring makes a choice to construct the delegate which later will be used for calling recover. It is constructed with target object invocation.getThis(), which points to the original object, i.e. a TEST_BdaProcessService instance. At this point, the code could simply use invocation.getProxy() instead, which would point to the AOP proxy, i.e. a TEST_BdaProcessService$$EnhancerBySpringCGLIB$$2f8076ac instance. The problem is that the target object reference is passed through to the point where recover gets called, and the corresponding recoverer instance at that point only knows the target object, having no clue of the corresponding proxy object anymore.

When I experimentally assigned the proxy to the delegate as a target, your advice method was invoked.

So we are talking about a Spring limitation here. Whether that was a deliberate choice in order to avoid any other related problems or simply an oversight, I have no idea.

enter image description here

Update: I created Spring Retry issue #244 on your behalf. You want to subscribe to it, so you can find out if/when it is going to be fixed.

Update 2: The issue has been fixed, is merged into the main branch and is probably going to be part of the upcoming 1.3.2 version, whenever that one might be released. For now, you can just clone Spring Retry, build by yourself and use the snapshot. I retested against your MCVE, the aspect now kicks in as expected for the recover method.

Upvotes: 3

Related Questions