Bug 333274 - Chained advice doesn't get applied on 2nd call to ProceedingJoinPoint#proceed()
Summary: Chained advice doesn't get applied on 2nd call to ProceedingJoinPoint#proceed()
Status: RESOLVED FIXED
Alias: None
Product: AspectJ
Classification: Tools
Component: Compiler (show other bugs)
Version: 1.6.10   Edit
Hardware: PC Linux
: P3 major (vote)
Target Milestone: 1.9.3   Edit
Assignee: aspectj inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-12-28 12:25 EST by Carlos Vara CLA
Modified: 2019-02-19 15:26 EST (History)
3 users (show)

See Also:


Attachments
Example project reproducing the problem (4.14 KB, application/octet-stream)
2010-12-28 12:27 EST, Carlos Vara CLA
no flags Details
Project that reproduces the bug in this issue [2nd upload 2010-01-22] (5.00 KB, application/x-zip-compressed)
2011-01-21 23:22 EST, Carlos Vara CLA
no flags Details
Patch that fixes the problem. (5.25 KB, patch)
2011-01-24 17:46 EST, Andrew Clement CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Carlos Vara CLA 2010-12-28 12:25:04 EST
When multiple aspects match the same call joinpoint, if one of the aspects calls proceed() more than once, these extra calls skip the other aspects and go directly to the method body.

So, assuming Aspect1 and Aspect2 matching the same method call, if Aspect1 precedes Aspect2, and Aspect1 calls proceed twice, the sequence current aspectj produces is as follows:
Aspect1 
-> Aspect2
-> -> method body
-> Aspect 2
Aspect 1
-> method body
Aspect1

While the expected sequence should be:
Aspect1 
-> Aspect2
-> -> method body
-> Aspect 2
Aspect 1
-> Aspect2
-> -> method body
-> Aspect 2
Aspect 1

I have been able to reproduce this behaviour in an AJDT project and with command line compiling.

Attached an AJDT project that shows the described problem.
Comment 1 Carlos Vara CLA 2010-12-28 12:27:18 EST
Created attachment 185863 [details]
Example project reproducing the problem
Comment 2 Andrew Clement CLA 2011-01-21 13:53:14 EST
When I unzipped your project, I noticed warnings on compilation because the declare precedence is annotation style and has the wrong package names in it for the aspects??

I fixed that, then compiled it but changed the advice bodies as follows to tell me what it was up to:


  public Object inAspect1(ProceedingJoinPoint pjp) throws Throwable {
        System.out.println(">In Aspect1");
        pjp.proceed();
        System.out.println("=In Aspect1");
        Object o = pjp.proceed();
        System.out.println("<In Aspect1");
        return o;
    }



   public Object inAspect2(ProceedingJoinPoint pjp) throws Throwable {
        System.out.println(">In Aspect2");
        Object o = pjp.proceed();
        System.out.println("<In Aspect2");
        return o;
    }



  public Object inAspect3(ProceedingJoinPoint pjp) throws Throwable {
        System.out.println(">In Aspect3");
        Object o =  pjp.proceed();
        System.out.println("<In Aspect3");
        return o;
    }


when I compile and run it I get (I have fixed the Precedence package names):

>In Aspect1
>In Aspect2
>In Aspect3
method body
<In Aspect3
<In Aspect2
=In Aspect1
>In Aspect2
>In Aspect3
method body
<In Aspect3
<In Aspect2
<In Aspect1
2

(I changed the method body to print 'method body'.)

This would appear to be the right output??  The two proceeds inside Aspect1 are calling out to Aspect2 which then calls out to Aspect3 which runs the advice.

Without my changes above (and keeping the warnings version of DeclarePrecedence), when I run it I get:

In Aspect2
In Aspect1
In Aspect3
In Aspect1
In Aspect3
2

Without precedence I am at the mercy of chance depending on where the aspects are loaded on the heap and the hashcodes they end up with.

That is on a mac, not on linux. and I was using 1.6.11-dev (but nothing has changed in 1.6.11 related to this).

I then changed the precedence to "ma.Aspect1,*" and tried again, to ensure the double proceed one is first, now when I run it:

In Aspect1
In Aspect2
In Aspect3
In Aspect1
In Aspect2
In Aspect3
2

Can you tell me if you meant the precedence to be like that?  With it modified, what precise output do you get from running the test program you attached.  thanks.
Comment 3 Carlos Vara CLA 2011-01-21 23:19:17 EST
Sorry, as you noticed I messed up and ended up uploading a wrong version of the project that doesn't reproduce the bug. I have uploaded a new project and double checked that the bug can be reproduced on this one.

There are 3 aspects, and the output I get by running the main method is:
>In Aspect1
>In Aspect2
>In Aspect3
Method call
<In Aspect3
<In Aspect2
=In Aspect1
Method call
<In Aspect1

Expected output would be:
>In Aspect1
>In Aspect2
>In Aspect3
Method call
<In Aspect3
<In Aspect2
=In Aspect1
>In Aspect2
>In Aspect3
Method call
<In Aspect3
<In Aspect2
<In Aspect1

From the outside, the bug seems a little sneaky, as you will notice that I have had to keep some "extra" code in 2 of the aspects or otherwise the behaviour is correct. You can check this by commenting out those lines in Aspect1 and Aspect3.
Comment 4 Carlos Vara CLA 2011-01-21 23:22:00 EST
Created attachment 187353 [details]
Project that reproduces the bug in this issue [2nd upload 2010-01-22]
Comment 5 Andrew Clement CLA 2011-01-24 17:38:14 EST
thanks for the test program.  I reduced it to just two aspects that showed the problem, rather than three.

What happens here is that when using annotation style advice, the proceeds aren't really handled properly.

A ProceedingJoinPoint knows about a single around closure.  Here we have multiple closures effectively being called whilst dealing with the same joinpoint.  A closure is associated with a PJP via a call to set$AroundClosure() on the joinpoint object.  On the first time through we setup the pjp with the first closure and call proceed, this first closure ends up calling the advice in the second aspect which sets up the pjp with the second closure and calls proceed (this prints 'method call').  We then unwind to the outer layer, the pjp is now configured with the second closure.  So when we 'proceed' on it, we skip the first closure entirely and print 'method call' again.

This problem needs a few conditions to occur:
- annotation style aspects
- around advice chain on the same joinpoint
- multiple proceeds in one of the around advices
- 'stuff' in the advice that prevents inlining (here it is the 'new XXX()' calls)

remove one of those conditions are the problem doesn't occur.

My immediate reaction would be write it in code style - but this then fails with a slightly different problem.  The inner types are private in the aspects but the advice bodies are inlined into the target types without raising the visibility of those types, resulting in a visibility problem when the code is run.  So not only does it have to be written in code style, but inlining has to be turned off with -XnoInline.

Solutions to the main problem here would seem to involve either repairing the closure pointer in the proceedingjoinpoint object (perhaps using a stack to record them rather than a field) or resetting the closure pointer by calling 'set$aroundclosure' again before calling the next proceed.

We want to avoid damaging performance here for annotation style around advice - ideally don't want anyone to pay a price unless they are in this kind of configuration.

The call that needs a subsequent call to repair/pop the closure looks like it is linkClosureAndJoinPoint.  This call is made on a closure and returns the joinpoint which is then passed to the advice call on the aspect:

invokespecial Main$AjcClosure1()
ldc 69648
invokevirtual AroundClosure.linkClosureAndJoinPoint(int) (returns PJP)
invokevirtual Aspect3.inTimeLimiterAspect(PJP) (returns somevalue)
invokestatic Conversions.intValue(Object)
ireturn

If we could call something after the advice returns that would do it (unlink or somesuch).
Comment 6 Andrew Clement CLA 2011-01-24 17:46:06 EST
Created attachment 187480 [details]
Patch that fixes the problem.

This is a workspace patch for AspectJ that will make the test pass.  It modifiers the aroundclosure object in the proceeding join point to be a stack rather than a single object.  It also generates code that goes after the advice call that 'pops' the previous entry from the stack.  With the fix in place the test in Ajc1611Tests passes.

However, this is a change to the runtime jar and moving from an object to a stack will currently affect all users of annotation style, whether they are doing a 'double proceed with chaining' or not.  Needs more thought.
Comment 7 Carlos Vara CLA 2011-01-25 19:14:29 EST
Thanks very much for the detailed description Andy.

I will try to run a bigger suite of code that had hit this bug against the provided patch to see if there is no other issues.

I'm afraid I cannot provide much at this point as my knowledge of aspectj internals is zero. Just a quick thought regarding performance: if the arc stack only gets used when the aspects are not inlined, maybe the performance hit won't be that big? After all, non inlined aspects are likely to be complex, so working on a small stack might not add much hit to it (I may however be very wrong in this assumption)
Comment 8 Carlos Vara CLA 2013-01-31 10:12:41 EST
Hi Andy,

Do you know what's the plan about including your bugfix in the 1.7 branch? About the bugfix reliability, I have been running a patched version of 1.6.11 without any issues for almost 2 years.
Comment 9 Andrew Clement CLA 2013-01-31 11:41:33 EST
I'll try and find time to take another look at it and evaluate inclusion.
Comment 10 Andrew Clement CLA 2013-06-24 11:07:36 EDT
unsetting the target field which is currently set for something already released
Comment 11 Yuyang Wang CLA 2019-02-10 01:59:52 EST
Hello.

It has been 5+ years since the last reply, and the same problem still exists in AspectJ v1.9.2. It would be great to fix it, since it is pretty useful in many cases (e.g. generic auto-retry aspect, etc.). Is there any plan to move forward, or clients are expected to find work-around themselves?

Thank you.
Comment 12 Andrew Clement CLA 2019-02-12 17:16:57 EST
The challenge with these kinds of issue is that the fix is quite intrusive and causes a performance degradation in all cases (as currently designed in that patch), whilst there is a relatively straightforward workaround of using code style aspects. However, I understand that may be considered not possible in some environments. Let me look over the proposed changes again, been a few years since i last did.
Comment 13 Yuyang Wang CLA 2019-02-13 19:27:30 EST
Thank you so much, Andrew!
Comment 14 Andrew Clement CLA 2019-02-19 15:26:16 EST
Ok, patch resurrected. It fixes some variants of the problem but because it wasn't also doing the 'unstack' of the closures in a finally block, if the proceed exits via exception it wasn't working in that case. I've fixed all that up. I've also added a recognition system so we will notice if we need to use stack vs single closure storage and so you will only suffer the performance degradation if you need it to be in place.  This does change the AspectJ runtime (adding some new methods in the JoinPoint infra). But as those new methods are only used in code generated to support this scenario, I don't think most folks will notice. I added them as default method implementations.

I did have to tweak the code gen to inject that finally block, probably the bit of code I'm most nervous about but all existing tests are passing. I'll keep an eye on feedback once the release is out.