exception during instrumentation

[hengels]

Hi,

I'm seeing another execption during method instrumentation. This time, the reason is not so obvious to me. Maybe someone could have a look at this:

[aopc] [debug] is advisable method: kopiereMitBeziehungen
 [aopc] [debug] does kopiereMitBeziehungen match execution(* wilken.basismodul.*->*(..)): false
 [aopc] [debug] does kopiereMitBeziehungen match execution(* wilken.informationssystem.*->*(..)): true
 [aopc] javassist.CannotCompileException: [source error] Method wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop not found in wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl
 [aopc] at javassist.CtBehavior.setBody(CtBehavior.java:194)
 [aopc] at javassist.CtBehavior.setBody(CtBehavior.java:163)
 [aopc] at org.jboss.aop.instrument.MethodExecutionTransformer.optimized(MethodExecutionTransformer.java:365)
 [aopc] at org.jboss.aop.instrument.MethodExecutionTransformer.instrument(MethodExecutionTransformer.java:199)
 [aopc] at org.jboss.aop.instrument.Instrumentor.transform(Instrumentor.java:573)
 [aopc] at org.jboss.aop.AspectManager.translate(AspectManager.java:572)
 [aopc] at org.jboss.aop.AspectManager.transform(AspectManager.java:490)
 [aopc] at org.jboss.aop.standalone.Compiler.compileFile(Compiler.java:258)
 [aopc] at org.jboss.aop.standalone.Compiler.compile(Compiler.java:191)
 [aopc] at org.jboss.aop.standalone.Compiler.main(Compiler.java:68)
 [aopc] java.lang.RuntimeException: failed to transform: wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl
 [aopc] at org.jboss.aop.instrument.Instrumentor.transform(Instrumentor.java:625)
 [aopc] at org.jboss.aop.AspectManager.translate(AspectManager.java:572)
 [aopc] at org.jboss.aop.AspectManager.transform(AspectManager.java:490)
 [aopc] at org.jboss.aop.standalone.Compiler.compileFile(Compiler.java:258)
 [aopc] at org.jboss.aop.standalone.Compiler.compile(Compiler.java:191)
 [aopc] at org.jboss.aop.standalone.Compiler.main(Compiler.java:68)
 [aopc] Caused by: java.lang.RuntimeException: code was: { if (aop$MethodInfo_getId_N_6040770469254561000.interceptors != (Object[])null || (_instanceAdvisor != null && _instanceAdvisor.hasInstanceAspects)) { org.jboss.aop.advice.Interceptor[] interceptors = aop$MethodInfo_getId_N_6040770469254561000.interceptors; if (_instanceAdvisor != null) { interceptors = _instanceAdvisor.getInterceptors(interceptors); } wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl_getId_N6040770469254561000_OptimizedMethodInvocation invocation = new wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl_getId_N6040770469254561000_OptimizedMethodInvocation(aop$MethodInfo_getId_N_6040770469254561000, interceptors); invocation.setTargetObject(this); invocation.typedTargetObject = this; invocation.setAdvisor(aop$classAdvisor$aop); return ($r)invocation.invokeNext(); } else { return wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop($$); }} for method getId
 [aopc] at org.jboss.aop.instrument.MethodExecutionTransformer.optimized(MethodExecutionTransformer.java:370)
 [aopc] at org.jboss.aop.instrument.MethodExecutionTransformer.instrument(MethodExecutionTransformer.java:199)
 [aopc] at org.jboss.aop.instrument.Instrumentor.transform(Instrumentor.java:573)
 [aopc] ... 5 more

This is the generated (reformatted) code:

if (aop$MethodInfo_getId_N_6040770469254561000.interceptors != (Object[])null
 || (_instanceAdvisor != null && _instanceAdvisor.hasInstanceAspects))
 {
 org.jboss.aop.advice.Interceptor[] interceptors = aop$MethodInfo_getId_N_6040770469254561000.interceptors;
 if (_instanceAdvisor != null) {
 interceptors = _instanceAdvisor.getInterceptors(interceptors);
 }
 wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl_getId_N6040770469254561000_OptimizedMethodInvocation invocation = new wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl_getId_N6040770469254561000_OptimizedMethodInvocation(aop$MethodInfo_getId_N_6040770469254561000, interceptors);
 invocation.setTargetObject(this);
 invocation.typedTargetObject = this;
 invocation.setAdvisor(aop$classAdvisor$aop);
 return ($r)invocation.invokeNext();
 }
 else {
 return wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop($$);
 }

<aop>
 <prepare expr="execution(* wilken.basismodul.*->*(..))"/>
 <prepare expr="execution(* wilken.informationssystem.*->*(..))"/>
</aop>

[hengels]

I've inserted an e,printStatckTrace in javaassist 3.0 and reproduced the error in order to get more information. It can't find a method. How come?

[aopc] compile error: Method wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop not found in wilken.informationssystem.berechtigung.BerichtBearbeitenBerechtigungImpl
 [aopc] at javassist.compiler.TypeChecker.atMethodCallCore(TypeChecker.java:648)
 [aopc] at javassist.compiler.TypeChecker.atCallExpr(TypeChecker.java:614)
 [aopc] at javassist.compiler.JvstTypeChecker.atCallExpr(JvstTypeChecker.java:156)
 [aopc] at javassist.compiler.ast.CallExpr.accept(CallExpr.java:45)
 [aopc] at javassist.compiler.CodeGen.doTypeCheck(CodeGen.java:235)
 [aopc] at javassist.compiler.CodeGen.compileExpr(CodeGen.java:222)
 [aopc] at javassist.compiler.CodeGen.atReturnStmnt2(CodeGen.java:591)
 [aopc] at javassist.compiler.JvstCodeGen.atReturnStmnt(JvstCodeGen.java:424)
 [aopc] at javassist.compiler.CodeGen.atStmnt(CodeGen.java:356)
 [aopc] at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 [aopc] at javassist.compiler.CodeGen.atStmnt(CodeGen.java:344)
 [aopc] at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 [aopc] at javassist.compiler.CodeGen.atIfStmnt(CodeGen.java:398)
 [aopc] at javassist.compiler.CodeGen.atStmnt(CodeGen.java:348)
 [aopc] at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 [aopc] at javassist.compiler.CodeGen.atStmnt(CodeGen.java:344)
 [aopc] at javassist.compiler.ast.Stmnt.accept(Stmnt.java:49)
 [aopc] at javassist.compiler.CodeGen.atMethodBody(CodeGen.java:285)
 [aopc] at javassist.compiler.Javac.compileBody(Javac.java:208)
 [aopc] at javassist.CtBehavior.setBody(CtBehavior.java:188)
 [aopc] at javassist.CtBehavior.setBody(CtBehavior.java:163)
 [aopc] at org.jboss.aop.instrument.MethodExecutionTransformer.optimized(MethodExecutionTransformer.java:365)
 [aopc] at org.jboss.aop.instrument.MethodExecutionTransformer.instrument(MethodExecutionTransformer.java:199)
 [aopc] at org.jboss.aop.instrument.Instrumentor.transform(Instrumentor.java:573)
 [aopc] at org.jboss.aop.AspectManager.translate(AspectManager.java:572)
 [aopc] at org.jboss.aop.AspectManager.transform(AspectManager.java:490)
 [aopc] at org.jboss.aop.standalone.Compiler.compileFile(Compiler.java:258)
 [aopc] at org.jboss.aop.standalone.Compiler.compile(Compiler.java:191)
 [aopc] at org.jboss.aop.standalone.Compiler.main(Compiler.java:68)

[kabirkhan]

Weird,

The instrumentor first creates a copy of your original method with a new name (wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop) and then modifies the method with the original name to call the introduced method.

I was wondering if it could be to do with the length of the name of the method, so I tried your example and it worked fine. Here's my version of the original class.

package wilken.informationssystem.berechtigung;

public class BerichtBearbeitenBerechtigungImpl
{
 public int getId()
 {
 return 2938;
 }

}

[hengels]

Hm, my getId method is marked final. But that's not the problem.

It hasn't todo anything with the method. If I narrow the include patternset, I get the same problem with another method.

Holger

[hengels]

The MemberResolver is comparing a full qualified method name with a short method name. I'm at the root of problem with a debugger. The MemberResolver compares

"<init>"
"berechneFakten"
"leseElemente"
...

with:

"wilken$informationssystem$dimension$DerivativeFaktenBerechner$berechneFakten$aop"

in a loop in line 96 of class MemberResolver (javaassist 3.0).

[kabirkhan]

The class should contain both a method called "berechneFakten" as well as a method called
"wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop". The one with the long name will contain the original method, while the method with the short name wil contain the hooks for AOP.

For the class I pasted in above, following instrumentation, this should look something like:

package wilken.informationssystem.berechtigung;

public class BerichtBearbeitenBerechtigungImpl implements Advised
{
 //Advisor fields get added
 Advisor _advisor = ...;
 InstanceAdvisor _instanceAdvisor = ...;
 public Advisor _getAdvisor(){return _advisor;}
 public InstanceAdvisor _getAdvisor(){return _instanceAdvisor;}

 //Introduced method contains the contents of original method
 public int wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop()
 {
 return 2938;
 }

 //The original method with your name with the hooks for AOP to happen
 public int getId()
 {
 if (aop$MethodInfo_getId_N_6040770469254561000.interceptors != (Object[])null || (_instanceAdvisor != null && _instanceAdvisor.hasInstanceAspects))
 {
 //Create invocation and invoke on it
 ...
 return invocation.invokeNext();
 }
 else
 {
 return wilken$informationssystem$berechtigung$BerichtBearbeitenBerechtigungImpl$getId$aop
();
 }

}

If you look at

org.jboss.aop.instrument.MethodExecutionTransformer.optimized()

you should see that the extra method is created first?

Can you please post some more information about what exactly you are doing? It sounds like it works for you "most of the time", what is different when it goes wrong?

[hengels]

Yes, a new method with the long name has been created and added. After adding the methods, they get renamed. However, if I browse the parameter clazz of the method "optimized", I see two methodInfos in CtClass->classFile with the original name and none with the long name.

Maybe renaming of the method doesn't propagate to the CtClass->classFile correctly?

.. unfortnately I have to leave the office for today

[kabirkhan]

There is only one MethodInfo per _original_ method. Its job is to keep track of the interceptors/advices for the method, and to link the original method to the wrapper method.

Does it always fall over at the same method? Does cleaning out all your classfiles between change the behaviour at all? How many classes are you weaving? etc.

[hengels]

When trying to lookup "wilken$informationssystem$dimension$DerivativeFaktenBerechner$berechneFakten$aop", the MemberResolver iterates over the following methods and doesn't find it:

[0] = "<init> ()V"
[1] = "berechneFakten ()Z"
[2] = "berechneFakten (Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Z"
[3] = "berechneFakten (Lwilken/informationssystem/dimension/Faktenspezifikation;)Z"
[4] = "finalizeProcess ()Z"
[5] = "finalizeProcessImmediate ()V"
[6] = "anlegeWertErmitllern (Lwilken/informationssystem/util/parser/faktenspezifikation/SimpleNode;)Z"
[7] = "anlegenDimensionsElemente ()Z"
[8] = "anlegeElemente (ILwilken/informationssystem/dimension/DimensionsRaumElement;)Z"
[9] = "leseElemente (I)Z"
[10] = "formelBerechnen (Lwilken/informationssystem/util/parser/faktenspezifikation/SimpleNode;)Ljava/math/BigDecimal;"
[11] = "ermittleWert (Ljava/lang/String;Ljava/lang/String;)Ljava/math/BigDecimal;"
[12] = "erfasseWert (Ljava/math/BigDecimal;)Z"
[13] = "prefeElementExistiertinDatenPool (Lwilken/informationssystem/hierarchie/ArbeitsHierarchieElement;)Z"
[14] = "<clinit> ()V"
[15] = "_getAdvisor ()Lorg/jboss/aop/Advisor;"
[16] = "_getInstanceAdvisor ()Lorg/jboss/aop/InstanceAdvisor;"
[17] = "_setInstanceAdvisor (Lorg/jboss/aop/InstanceAdvisor;)V"
[18] = "berechneFakten ()Z"

Please note that index 1 and 18 have the same name and signature and there's really no method with the long name (original body). Thus the MemberResolver behaves correct.

Afterwards, the MemberResolver recursively calls lookupMethod withe the superclass and so on. Finally it returns null and the caller (TypeChecker->atMethodCallCore) throws a CompileError.

My suspicion is, that renaming the original method in MethodExecutionTransformer->optimized fails (method.setName(wrappedName);). And later, during compilation of the wrapper method, the compiler cannot find the original method with the long name, because it was not renamed correctly.

Do you think, this is the possible reason?

Does it always fall over at the same method? Does cleaning out all your classfiles between change the behaviour at all? How many classes are you weaving?

If I run the aopc with the same preconditions (fresh classfiles, same include set), it fails always at the same method. Though this is not the only method. If I try to instrument different classes, the same error occures in other places, too. I'm weaving a small subset from more than 16000 classes, linked again heavy jars.

Holger

[hengels]

I made a really strange observation.

If I instrument the class as part of some list of classes, it might fail. If I instrument it separately or as part of a different list of classes, it succeeds !?!?!? Event if it's the same set of classes, it migh succed, if specified in one order but fails, if specified in the another order.

for example:

aopc.sh $CP -aoppath etc/instrument-aop.xml classes/wilken/informationssystem/berichtswesen classes/wilken/informationssystem/dimension

-> fails

aopc.sh $CP -aoppath etc/instrument-aop.xml classes/wilken/informationssystem/dimension classes/wilken/informationssystem/berichtswesen

-> succeeds

BTW: I fixed another bug in javaassist http://www.jboss.org/index.html?module=bb&op=viewtopic&t=64091 .. I hope somebody will apply the patches.

[hengels]

Hi Kabir,

thanks for your help. finally I managed to localize the bug in javaassist. The workaround is to comment out the call to doCompaction in CtClassType->getClassFile2

The reson is, that the method doCompaction calls CtClassType->isModified in order to check, if a class can be removed from the cache. isModified returns the field "wasChanged". The latter isn't updated on changes (see method checkModify).

So, what actually happens is that modified classes are pruned from the cache and thus, the modifications get lost. this is the reason, why the compiler couldn't find the renamed method.

Regards,

Holger

[kabirkhan]

Great,

These are the kind of "border-line use cases" that are only found in real world scenarios. Thanks a lot for your help:-)

Bill is on holiday this week, but I'll have a word with him about adding your fixes next week since he knows the javassist internals better than me.

http://jira.jboss.org/jira/browse/JBAOP-140