Bug 525541 - AspectJ Internal Compile Error when saving modified *.aj aspect likely due to lambda
Summary: AspectJ Internal Compile Error when saving modified *.aj aspect likely due to...
Status: NEW
Alias: None
Product: AspectJ
Classification: Tools
Component: Compiler (show other bugs)
Version: 1.8.10   Edit
Hardware: Macintosh Mac OS X
: P3 major (vote)
Target Milestone: ---   Edit
Assignee: aspectj inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-10-04 04:41 EDT by bandolero perez CLA
Modified: 2017-10-23 17:48 EDT (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description bandolero perez CLA 2017-10-04 04:41:45 EDT
This is kinda random, sometimes it repeats several times in a row and then stops happening.
Context that might be relevant:
- Just updated to AspectJ Compiler 1.8.10.201710032234 as per Eclipse update prompt.
- Changed a line of code in an around() advice from: 
logger.trace(thisJoinPoint.getSignature().getName() + ", query: " + pipeline);
to
logger.trace("{}, pipeline: {}", () -> ((JoinPoint.StaticPart)thisJoinPointStaticPart).getSignature().getName(), () -> pipeline);

So it might be related to the lambda.

----

java.lang.RuntimeException
at org.aspectj.apache.bcel.classfile.ConstantPool.constantToString(ConstantPool.java:212)
at org.aspectj.apache.bcel.classfile.ConstantPool.constantToString(ConstantPool.java:254)
at org.aspectj.apache.bcel.classfile.Utility.codeToString(Utility.java:1002)
at org.aspectj.apache.bcel.classfile.Utility.codeToString(Utility.java:160)
at org.aspectj.apache.bcel.classfile.Code.getCodeString(Code.java:372)
at org.aspectj ... (AutoBuildJob.java:232)
at org.eclipse.core.internal.jobs.Worker.run(Worker.java:56)

Compile error: RuntimeException thrown: Unknown constant type 18
Comment 1 bandolero perez CLA 2017-10-05 03:28:56 EDT
It's a PITA, keeps happening very often on editor save.
Comment 2 Andrew Clement CLA 2017-10-05 12:14:47 EDT
let me take a look... constant pool tag 18 is for default annotation values.  Shouldn't be related to lambdas. If you switch back from the lambda, does the problem go away?
Comment 3 Andrew Clement CLA 2017-10-05 12:16:41 EDT
actually could be it wants to report a problem with the lambda but the code to report the problem is hitting something else (the 18 tag)
Comment 4 bandolero perez CLA 2017-10-05 12:30:43 EDT
As soon as I comment out the log statements that contain the lambdas it's happy. 
If I uncomment them the nag is back. I have to Project > Clean to force a full rebuild.
Comment 5 Andrew Clement CLA 2017-10-05 12:36:49 EDT
no, my mistake again, I was looking at the wrong set of constants! 18 is invokedynamic, but I still think it is related to it trying to tell us about a real problem and blowing up during the error reporting. I will have a build up that fixes this exception, but it may just reveal the real problem when you try on that build.

Using lambdas in around advice is a tricky business because they prevent the inlining from occurring (because we don't currently copy around the constant pool stuff related to lambdas so we have to leave the around advice itself in the aspect) but as far as I recall that all happens automatically (the -XnoInline flag is turned on when the situation is discovered).  Actually you could try manually setting that option on your project in the aspectj preferences to see if it made any difference, whilst waiting for the build.  If that option made a difference it is the detection logic for switching the option on.
Comment 6 bandolero perez CLA 2017-10-05 12:52:27 EDT
yep, with the -XnoInline option I don't see the error popping up.

This is an excerpt from the aspect code, that intercepts certain MongoDB driver calls to add a comment element with a traceId for tracing:
public aspect DBTracingAspect {
  private static Logger logger = LogManager.getLogger("DBTracing");
  pointcut cwServerCflow() :
    cflow(execution(* com.farmerswife.cloudwife.server..*(..)));

  pointcut combinedPC(DBObject query) :
    (call(* *DBCollection.findAnd*(DBObject, ..)) || call(* *DBCollection.remove(DBObject, ..)) || call(* *DBCollection.update(DBObject, ..)))
    && args(query, ..);

  Object around(DBObject query) : combinedPC(query) && cwServerCflow() && !cflowbelow(combinedPC(DBObject)) {
    if (query == null) return proceed(query);
    DBObject newQuery = addCommentToQueryObj(query);
    logger.trace("{}, query: {}", () -> ((JoinPoint.StaticPart)thisJoinPointStaticPart).toString(), () -> newQuery);
    return proceed(newQuery);
 }
//...
}

It's the log4j logging with lambdas what seems to be triggering the issue. Note that I have to do that akward JoinPoint.StaticPart casting to keep the lambda happy.
Comment 7 Andrew Clement CLA 2017-10-05 14:19:38 EDT
Thanks for trying that. The build is through now for the problem with the fix for:

java.lang.RuntimeException
at org.aspectj.apache.bcel.classfile.ConstantPool.constantToString(ConstantPool.java:212)

but as i say, i think it'll just reveal another issue. We seem to have a workaround for you right now though, if you are happy with -XnoInline setting?
Comment 8 bandolero perez CLA 2017-10-05 18:35:01 EDT
I´m not really sure what the implications of using this `noInline` option are. That is, besides what the docs say about making code more digestible for the debugger. Are the produced binaries different in any way? 

Deployable code is built with Maven by Jenkins CI with the aspect stuff handled by the AspectJ Maven Plugin so I presume there´s nothing stopping us from using `noInline` in Eclipse preferences on the developers machines and leave the Maven config as is for the real builds right?
Comment 9 Andrew Clement CLA 2017-10-05 19:28:43 EDT
-XnoInline is like any inlining - you inline to try and get better performance. In the case of around advice if you inline it means instead inserting the advice code directly where it matches, without inlining you instead insert calls to the advice code. So, yes, it produces different binaries.

The real bug here seems to be that you used lambda in advice which should have flipped it to non inlining automatically under the covers, but that isn't working.  To make inlining work for around advice using lambdas we have to do a bunch more engineering to copy the infrastructure that will support the created invokedynamic for the lambda from the aspect to the affected target.

I would presume if the maven plugin builds this code it should hit the same problem, it isn't specific to the IDE that you are seeing the issue (if it is what we think it is). So you'd need to turn the noinline option on in the maven config too.  I would look at this right now but I'm up to my neck in AspectJ9 and building modules :) I will try to get to the right fix in a timely fashion. If we had a minimal testcase that showed it going wrong, that would speed things along.
Comment 10 bandolero perez CLA 2017-10-06 04:43:19 EDT
Hi again!
I've updated ADJT using sw site http://download.eclipse.org/tools/ajdt/47/dev/update
I've disabled -XnoInline and now it compiles just fine with the lambdas. Tested commenting and uncommenting them out and I see no more errors. 

For the record this is the output from the AJDT Trace Event console showing my config options:

10:24:19 Startup information: 
   AJDT version: 2.2.4.201710051806
   AspectJ Compiler version: 1.8.11
   usingVisualiser=true
   usingXref=true
   usingCUprovider=true
   org.aspectj.ajdt.core.compiler.BuildOptions.showweavemessages = true
   org.aspectj.ajdt.core.compiler.lint.CannotImplementLazyTJP = warning
   org.aspectj.ajdt.core.compiler.lint.unorderedAdviceAtShadow = warning
   org.aspectj.ajdt.core.compiler.lint.noGuardForLazyTjp = warning
   ajde.version.at.previous.startup = 2.2.4.201710051806
   org.aspectj.ajdt.core.complier.lint.aspectExcludedByConfiguration = warning
   org.aspectj.ajdt.core.compiler.lint.multipleAdviceStoppingLazyTjp = warning
   org.aspectj.ajdt.core.compiler.weaver.verbose = true
   org.eclipse.ajdt.core.compiler.nonStandardOptions = -warn:-allOver-ann
   org.aspectj.ajdt.core.compiler.lint.WildcardTypeName = warning
   org.eclipse.ajdt.internal.ui.tracing.checked.filters = set: Compiler,Builder
   org.aspectj.ajdt.core.compiler.lint.adviceDidNotMatch = error
   org.aspectj.ajdt.core.compiler.lint.swallowedExceptionInCatchBlock = warning
10:24:23 AspectJ reports build successful, build was: FULL
10:24:23 AJDE Callback: finish. Was full build: true
...
Comment 11 Andrew Clement CLA 2017-10-23 17:48:04 EDT
Not quite sure where the errors have gone ! - but there are other things we learn from the code that flip it into a no inlining state, maybe you are triggering one of those. If so that'll work for AJDT and for maven builds.