Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Two Aspect Class,two around,get emptystack error #128

Closed
walt2021 opened this issue Feb 25, 2022 · 7 comments · Fixed by #132
Closed

Two Aspect Class,two around,get emptystack error #128

walt2021 opened this issue Feb 25, 2022 · 7 comments · Fixed by #132
Labels
enhancement New feature or request
Milestone

Comments

@walt2021
Copy link

walt2021 commented Feb 25, 2022

Edited by @kriegaex

When i use the code , i get the error(aspectj is 1.9.6)

java.util.EmptyStackEcxeption
    at java.util.Stack.peek(Stack.java:102)
    at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:180)
    .....run()

However,i use 1.9.1,it is ok
I need help,thank you.

@Aspect
@DeclarePrecedence(BB,AA)
public class AA{
    @Pointcut
    .....
    
    @Around
    public Object around(){
        Thread{
             point.proceed
        }
    }
}
@Aspect
public class BB{
    @Pointcut
    .....
    
    @Around
    public Object around(){
             point.proceed
    }
}
@kriegaex
Copy link
Contributor

kriegaex commented Feb 25, 2022

Please reformat your question, using code blocks correctly. It is hard to read your code without copying it into an editor. Please also do not post pseudo code. What you posted would not compile (e.g. lower-case annotation names). Post complete classes with package names and imports, then others can at least try to reproduce your problem. If you want to learn how to ask good questions (not just here, but anywhere), please read the MCVE article. Thank you.

@walt2021
Copy link
Author

walt2021 commented Feb 25, 2022

Edited by @kriegaex

Thank you very much

I use an android project which use aspectj1.9.6

When i call method testMethod(), i get the error:

2022-02-25 17:01:05.827 14000-14000/com.example.myapplication D/blue: AA before time = 1645779665827
2022-02-25 17:01:05.827 14000-14000/com.example.myapplication D/blue: BB before time = 1645779665827
2022-02-25 17:01:05.827 14000-14000/com.example.myapplication D/blue: AA after time = 1645779665827
2022-02-25 17:01:05.828 14000-16080/com.example.myapplication D/blue: BB 2
2022-02-25 17:01:05.828 14000-16080/com.example.myapplication W/System.err: java.util.EmptyStackException
2022-02-25 17:01:05.829 14000-16080/com.example.myapplication W/System.err:     at java.util.Stack.peek(Stack.java:102)
2022-02-25 17:01:05.829 14000-16080/com.example.myapplication W/System.err:     at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:170)
2022-02-25 17:01:05.829 14000-16080/com.example.myapplication W/System.err:     at com.example.myapplication.BBAspect$1.run(BBAspect.java:25)
2022-02-25 17:01:05.829 14000-16080/com.example.myapplication W/System.err:     at java.lang.Thread.run(Thread.java:923)

This is my demo

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface AA {
}
@Aspect
@DeclarePrecedence("com.example.myapplication.AAAspect,com.example.myapplication.BBAspect")
public class AAAspect {
    @Pointcut("execution(@com.example.myapplication.AA * *..*(..))")
    public void allMethod(){

    }

    @Around("allMethod() && @annotation(param)")
    public Object arounddd(ProceedingJoinPoint point, AA param) throws Throwable{
        Log.d("blue", "AA before time = " + System.currentTimeMillis());
        Object[] args = point.getArgs();
        Object obj = point.proceed(args);
        Log.d("blue", "AA after time = " + System.currentTimeMillis());
        return obj;
    }
}
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface BB {
}
@Aspect
public class BBAspect {
    @Pointcut("execution(@com.example.myapplication.BB * *..*(..))")
    public void allMethod(){

    }

    @Around("allMethod() && @annotation(param)")
    public Object arounddd(ProceedingJoinPoint point, AA param) throws Throwable{
        Log.d("blue", "BB before time = " + System.currentTimeMillis());
        new Thread(new Runnable() {
            @Override
            public void run() {
                try {
                    Log.d("blue", "BB 2");
                    point.proceed();
                } catch (Throwable throwable) {
                    throwable.printStackTrace();
                }
            }
        }).start();
        return null;
    }
}
public class Test {

    @AA
    @BB
    public void testMethod(){
        Log.d("blue", "testMethod");
    }
}

@kriegaex
Copy link
Contributor

Preface

Seriously? I asked you to edit your question and add more information, not to post more pseudo code in bogus, unreadable formatting. Sorry for lecturing you, but if you cannot even do that, I have low motivation to read your code and error log, because it simply hurts my eyes. Am I asking too much for you to click on the formatting icons on the top of the input field or learn markdown?

Besides, your code with all the falsely lower-case AspectJ annotations would still not compile and is just pseudo code to me. Both pointcuts also have syntax errors and would never compile with the AspectJ compiler. Do you ever test your own code before posting it?

Let me show you what I mean: correct annotation names starting with upper-case characters like @Aspect, @Retention (not @aspect, @retention), one code block per class and per console log snippet. Maybe you even feel like adding syntax highlighting hints, if you want to do it more nicely.

Fixed, complete example code

package com.example.myapplication;

import static java.lang.annotation.ElementType.METHOD;
import static java.lang.annotation.RetentionPolicy.RUNTIME;

import java.lang.annotation.Retention;
import java.lang.annotation.Target;

@Retention(RUNTIME)
@Target(METHOD)
public @interface AA {}
package com.example.myapplication;

import static java.lang.annotation.ElementType.METHOD;
import static java.lang.annotation.RetentionPolicy.RUNTIME;

import java.lang.annotation.Retention;
import java.lang.annotation.Target;

@Retention(RUNTIME)
@Target(METHOD)
public @interface BB {}
package com.example.myapplication;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.DeclarePrecedence;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
@DeclarePrecedence("com.example.myapplication.AAAspect, com.example.myapplication.BBAspect")
public class AAAspect {
  @Pointcut("execution(@com.example.myapplication.AA * *(..))")
  public void allMethod() {}

  @Around("allMethod() && @annotation(param)")
  public Object arounddd(ProceedingJoinPoint point, AA param) throws Throwable {
    System.out.println("blue - AA before time = " + System.currentTimeMillis());
    Object[] args = point.getArgs();
    Object obj = point.proceed(args);
    System.out.println("blue - AA after time = " + System.currentTimeMillis());
    return obj;
  }
}
package com.example.myapplication;

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 BBAspect {
  @Pointcut("execution(@com.example.myapplication.BB * *(..))")
  public void allMethod() {}

  @Around("allMethod() && @annotation(param)")
  public Object arounddd(ProceedingJoinPoint point, AA param) throws Throwable {
    System.out.println("blue - BB before time = " + System.currentTimeMillis());
    new Thread(new Runnable() {
      @Override
      public void run() {
        try {
          System.out.println("blue - BB 2");
          point.proceed();
        }
        catch (Throwable throwable) {
          throwable.printStackTrace();
        }
      }
    }).start();
    return null;
  }
}
package com.example.myapplication;

public class Test {
  @AA
  @BB
  public void testMethod() {
    System.out.println("blue - testMethod");
  }

  public static void main(String[] args) {
    new Test().testMethod();
  }
}
blue - AA before time = 1645792424231
blue - BB before time = 1645792424234
blue - AA after time = 1645792424235
blue - BB 2
java.util.EmptyStackException
	at java.base/java.util.Stack.peek(Stack.java:102)
	at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:170)
	at com.example.myapplication.BBAspect$1.run(BBAspect.aj:21)
	at java.base/java.lang.Thread.run(Thread.java:834)

Now I can read the code, compile and execute it as well as reproduce your problem. I also do not need an unknown log framework to the example project.

Fixing a small bug (not the error root cause, but anyway)

First, please note that there is a bug in BBAspect:

public class BBAspect {
  @Pointcut("execution(@com.example.myapplication.BB * *(..))")
  public void allMethod() {}

  @Around("allMethod() && @annotation(param)")
  public Object arounddd(ProceedingJoinPoint point, AA param) throws Throwable {

It should be BB param. It only happens to work in your example, because the test method carries both annotations. But that is not the error causing the problem.

Let us also add another log line in the same aspect before the return statement:

    }).run();
    System.out.println("blue - BB after time = " + System.currentTimeMillis());
    return null;
  }
}

The console log becomes:

blue - AA before time = 1645793630464
blue - BB before time = 1645793630465
blue - BB after time = 1645793630466
blue - AA after time = 1645793630466
blue - BB 2
java.util.EmptyStackException
	at java.base/java.util.Stack.peek(Stack.java:102)
	at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:170)
	at com.example.myapplication.BBAspect$1.run(BBAspect.aj:21)
	at java.base/java.lang.Thread.run(Thread.java:834)

So we see that both around-aspects do their jobs and return correctly. What is obviously still missing is the "blue - testMethod" output from the target method.

Experimentally executing without spawning off a new thread

I can already tell you that this is because of your asynchronous proceed() in the extra thread. That without multi-threading it would work correctly, we can easily test by changing .start() to .run(), so we have everything in one thread. The log output changes to:

blue - AA before time = 1645793834174
blue - BB before time = 1645793834176
blue - BB 2
blue - testMethod
blue - BB after time = 1645793834178
blue - AA after time = 1645793834178

There we have out "blue - testMethod" and no more exception.

The root cause

Now why is that? Because in JoinPointImpl we have:
https://github.com/eclipse/org.aspectj/blob/0fe9c68ec1aecdd80798b0113bb02325162e2f36/runtime/src/main/java/org/aspectj/runtime/reflect/JoinPointImpl.java#L139-L143

And later we have:
https://github.com/eclipse/org.aspectj/blob/0fe9c68ec1aecdd80798b0113bb02325162e2f36/runtime/src/main/java/org/aspectj/runtime/reflect/JoinPointImpl.java#L161-L172

What does that mean? Because around-advice methods need to be executed onion-skin style, i.e. entered outside-in and exited inside-out, we use a Stack<AroundClosure> in order to track the situation. As we can see in the error log above, ...

blue - BB after time = 1645793630466
blue - AA after time = 1645793630466
blue - BB 2
java.util.EmptyStackException

... both around-aspects have already finished doing their jobs when suddenly in the new thread you are trying to proceed - but the stack of around-closures is empty already. This is simply a user error. Around advices are not supposed to proceed asynchronously, if there is a nesting situation, i.e. more than one around-advice advising the exact same joinpoint.

If you temporarily comment out the advice annotation in AAAspect in order to deactivate it, ...

//  @Around("allMethod() && @annotation(param)")
  public Object arounddd(ProceedingJoinPoint point, AA param) throws Throwable {

and also add a little waiting time in the main method in order to wait for the asynchronous thread to finish so we can see its log output, ...

  public static void main(String[] args) throws InterruptedException {
    new Test().testMethod();
    Thread.sleep(2000);
  }

the program with proceed() the extra thread works:

blue - BB before time = 1645795119829
blue - BB after time = 1645795119831
blue - BB 2
blue - testMethod

Lesson learned: Please do not proceed asynchronously in a nested around-advice situation!

I am sorry to have no better news for you, but you simply cannot make nested around-advices asynchronous. From AspectJ's perspective, both advice methods have terminated already and the closures discarded when suddenly you want to proceed.

Besides, even in the situation where you only have one around-advice per method, you can execute the target method asynchronously, but if the advice already returned a result to the calling method (if the target method has non-void return type), the result of the proceed() call would simply vanish into nothingness, unless the executing thread does something with it independently of the target method's original caller, or if the target method happens to have a Future return type. Then you could play a smart trick, returning a future without result from the advice first, then set the future's result later in the other thread after proceeding and waiting for the original future's value to become available. But if you are working with futures already, chances are that the program is designed to use multi-threading already and proceeding in an extra thread is not necessary in the first place.

Last, but not least: Questions like this belong on Stack Overflow or the AspectJ users mailing list. GitHub issues are for bugs. I am answering it, because I do believe you that you thought there is a bug in AspectJ.

@kriegaex
Copy link
Contributor

i get the error (aspectj is 1.9.6) java.util.EmptyStackEcxeption (...)

However, i use 1.9.1, it is ok

@aclement, this made me think about what has changed between then and now. 1.9.1 was published in April 2018, 1.9.6 in July 2020. Other than you mavenising the project and moving the class to another folder, actually there was only one relevant change: 8819fad, see also Bugzilla #333274. This is where you introduced the stack in order to be able to handle problems related to proceeding multiple times, e.g. for aspects re-trying things. The change became effective in 1.9.3. Since then, what the OP was trying here no longer works. I did not try, but I believe him when he says that in 1.9.1 he could do this. Do you see a way to fix this without reverting the useful change in the commit I just mentioned?

@kriegaex
Copy link
Contributor

Running the program under AspectJ 1.9.2

@aclement, quick update: Like @walt2021 said, this particular scenario works in 1.9.2. I added some stack trace info to the target method, so we see where it was called from:

  @AA
  @BB
  public void testMethod() {
    System.out.println("blue - testMethod - called by " + new Exception().getStackTrace()[3]);
  }

Like I said, the following logs are all from AspectJ 1.9.2.


Proceeding exactly once from both aspects like in the example above yields:

blue - AA before time = 1645842700066
blue - BB before time = 1645842700067
blue - BB after time = 1645842700069
blue - AA after time = 1645842700069
blue - BB 2
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:22)

Proceeding twice in the synchronously proceeding AAAspect yields:

blue - AA before time = 1645842785833
blue - BB before time = 1645842785835
blue - BB after time = 1645842785836
blue - BB 2
blue - testMethod - called by com.example.myapplication.AAAspect.arounddd(AAAspect.aj:20)
blue - AA after time = 1645842785837
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:22)

I.e. interestingly, only one target method execution comes from "inner" of the two nested around-aspects BBAspect, the other one from the "outer" one AAAspect. This might be one of the reasons you introduced the stack in 1.9.3, because you wanted to avoid that. (I am just speculating.)


Proceeding twice in the asynchronously proceeding BBAspect instead yields:

blue - AA before time = 1645843079117
blue - BB before time = 1645843079119
blue - BB after time = 1645843079120
blue - AA after time = 1645843079120
blue - BB 2
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:21)
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:22)

Here, everything is as expected, i.e. both target method executions are triggered by the "inner" asynchronous aspect.


Proceeding twice in both aspects yields:

blue - AA before time = 1645843174505
blue - BB before time = 1645843174506
blue - BB after time = 1645843174507
blue - BB 2
blue - testMethod - called by com.example.myapplication.AAAspect.arounddd(AAAspect.aj:20)
blue - AA after time = 1645843174508
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:21)
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:22)

Now we do not have anything like 2*2=4 executions, but 2 from the "inner" asynchronous aspect plus one more from the "outer" synchronous one, all in all 3 executions.

Running the program under AspectJ 1.9.8 (1.9.3+)

Because of the stack problem, we cannot spawn the extra thread, but if again I am replacing Thread.start() by run(), we see that in all 4 scenarios, the target method executions always originate from the "inner" aspect BBAspect, i.e. the mixed-up mess from 1.9.2 no longer exists in 1.9.3+ and the stack works. The consequence is also that in the case of both aspects proceeding twice, we now do have 2*2=4 executions, but all coming from the "inner" aspect:

blue - AA before time = 1645843459198
blue - BB before time = 1645843459199
blue - BB 2
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:21)
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:22)
blue - BB after time = 1645843459200
blue - BB before time = 1645843459200
blue - BB 2
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:21)
blue - testMethod - called by com.example.myapplication.BBAspect$1.run(BBAspect.aj:22)
blue - BB after time = 1645843459201
blue - AA after time = 1645843459201

This is wonderful, perfect nesting. We see that the "inner" aspect is triggered twice completely and each time proceeds twice. The only downside is that this only works synchronously. I am going to play with the source code and see if I can synchronise on the stack object somehow.

Sorry for the lengthy post, but I do want to document my findings for reference.

kriegaex added a commit to kriegaex/aspectj that referenced this issue Feb 26, 2022
If we do not synchronise, we will run into problems with nested
around-aspects in combination with proceeding asynchronously (in another
thread).

Fixes eclipse-aspectj#128.

Signed-off-by: Alexander Kriegisch <[email protected]>
kriegaex added a commit to kriegaex/aspectj that referenced this issue Feb 26, 2022
Otherwise, we would jeopardise asynchronous proceeding, see
eclipse-aspectj#129 (comment)

Instead, we
  - keep the stack,
  - but treat it like a list (Stack implements the List interface),
  - keeping a current closure index,
  - using 'get(currentArcIndex)' instead of `peek()` and `pop()`.

Fixes eclipse-aspectj#128.

Signed-off-by: Alexander Kriegisch <[email protected]>
kriegaex added a commit to kriegaex/aspectj that referenced this issue Feb 26, 2022
kriegaex added a commit to kriegaex/aspectj that referenced this issue Feb 28, 2022
In case of asynchronous proceeding for nested around-advice, child
threads need copies of the original around-closure stack. Otherwise, the
target method thread will have popped the stack empty after unwinding.

Fixes eclipse-aspectj#128.

Signed-off-by: Alexander Kriegisch <[email protected]>
kriegaex added a commit to kriegaex/aspectj that referenced this issue Feb 28, 2022
@walt2021
Copy link
Author

walt2021 commented Mar 1, 2022

Thank you very much again.
I have learn much.

@kriegaex
Copy link
Contributor

kriegaex commented Mar 1, 2022

Let me know if you agree to test a snapshot version with the bugfix for your situation and provide feedback, testing on Android. I can publish it on the Sonatype OSSRH snapshot Maven repository later today when I have some spare time.

@kriegaex kriegaex added the enhancement New feature or request label Mar 21, 2022
@kriegaex kriegaex added this to the 1.9.9 milestone Mar 21, 2022
kriegaex added a commit that referenced this issue Mar 23, 2022
In case of asynchronous proceeding for nested around-advice, child
threads need copies of the original around-closure stack. Otherwise, the
target method thread will have popped the stack empty after unwinding.

Fixes #128.

Signed-off-by: Alexander Kriegisch <[email protected]>
kriegaex added a commit that referenced this issue Mar 23, 2022
kriegaex added a commit to kriegaex/aspectj that referenced this issue Mar 23, 2022
kriegaex added a commit that referenced this issue Mar 6, 2024
Leak was introduced in commit 3c80a36, fixing #128, but introducing
#288 instead, which was the lesser of two evils, but still bad for some
users unwilling to use native AspectJ syntax for their aspects, avoiding
the problem.

Relates to #288.

Signed-off-by: Alexander Kriegisch <[email protected]>
kriegaex added a commit that referenced this issue Mar 12, 2024
Leak was introduced in commit 3c80a36, fixing #128, but introducing
#288 instead, which was the lesser of two evils, but still bad for some
users unwilling to use native AspectJ syntax for their aspects, avoiding
the problem.

Relates to #288.

Signed-off-by: Alexander Kriegisch <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
2 participants