Hi,
Tricky to diagnose without a small failing sample.
Have you definetly confirmed the advice actually isn't being called?
Or are you inferring that because the log messages aren't prefixed? I
just wonder if a System.out.println() in the before/after advice may
tell us if the advice is actually running. It would seem very strange
for the other before() advice to run and yet the MDC related advices
not to run.
Also, just to note:
before():(duringMyOp() && !within(*..*Aspect) && !logCall() ) { ... etc
the 'duringMyOp()' is actually redundant here because all advice in a
'percflow(X)' aspect has the implicit additional condition of '&&
cflow(X)'. It does no harm though as the pointcut optimizer will be
discarding the dup.
> Another possible clue might be(in the compilation) ...
>
> [WARNING] does not match because declaring type is java.lang.Object, if match
> desired use target(org.apache.log4j.Logger) [Xlint:unmatchedSuperTypeInCall]
That would just be at one joinpoint though (if you see it once) - I
imagine you are expecting many joinpoints to hit. Perhaps another
interesting datapoint would be changing it to be a call to something
else. However, that wouldn't explain why it works in your prototype
and not in the real app.
cheers
Andy
On 3 June 2011 10:53, Abhijit Inamdar <ainam...@intrepidls.com> wrote:
> One other thing ... I mentioned "my prototype" and "my real app" in my
> original post and it seems that in your original reply you may have
> misunderstood that to mean that I was trying load time weaving. Actually
> neither use load time weaving. "My prototype" only refers to a toy app I
> have to learn AspectJ, while "my real app" is the production app that I am
> trying to enhance with AspectJ. The pointcuts in the two are identical
> besides the fact that the paths in myOp() look different
> (com.mycompany.myapp.webservices..*(..) vs ajia.messaging..*(..)). In the
> prototype both myOp() and logCall() work exactly as expected while in the
> real app only myOp() works while logCall() doesn't.
> ________________________________________
> From: aspectj-users-boun...@eclipse.org [aspectj-users-boun...@eclipse.org]
> on behalf of Abhijit Inamdar [ainam...@intrepidls.com]
> Sent: Friday, June 03, 2011 10:35 AM
> To: aspectj-users@eclipse.org
> Subject: Re: [aspectj-users] Puzzling problem using AspectJ
>
> Hi Andy,
> Just to clarify, my aspect looks like this
>
> *************************************************
> public aspect ChainAspect percflow(myop()) { ...
>
> <snipped>
> private static final String MDC_KEY = "caller";
>
> pointcut logCall() : call(* org.apache.log4j.Logger.*(..)) &&
> !within(*..*Aspect);
>
> before() : logCall() {
> MDC.put(MDC_KEY, " " + myId + " " + depth++ + " " + " (" +
> thisEnclosingJoinPointStaticPart.getSourceLocation()
> + ") " +
> thisEnclosingJoinPointStaticPart.getSignature().toShortString());
> }
>
> after() : logCall() {
> MDC.remove(MDC_KEY);
> }
>
> pointcut myop(): call(* com.mycompany.myapp.webservices..*(..)) ;
>
> pointcut duringMyOp() : cflow(myop());
>
> before():(duringMyOp() && !within(*..*Aspect) && !logCall() ) { ... etc
>
> *************************************************
>
> The before advice for myop() works fine. It basically logs entry into
> methods(basic tracing) with a unique Id per cflow and depth of the call.
> the logCall() pointcut is intended to wrap existing logging with the unique
> Id of the cflow. The logCall() pointcut is the one that does not seem to
> work. i.e. neither the before nor the after advice for it is never entered.
> In the bytecode below myOp() seems to be myAspect$4$48864b4c, while logCall()
> is myAspect$3$58016c43.
>
> Another possible clue might be(in the compilation) ...
>
> [WARNING] does not match because declaring type is java.lang.Object, if match
> desired use target(org.apache.log4j.Logger) [Xlint:unmatchedSuperTypeInCall]
>
> Google shows old discussion about how this is an unhelpful and possibly
> misleading message.
>
> Thanks for all your help,
> Abhi
>
>
>
>
>
>
>
> ________________________________________
> From: aspectj-users-boun...@eclipse.org [aspectj-users-boun...@eclipse.org]
> on behalf of Andy Clement [andrew.clem...@gmail.com]
> Sent: Friday, June 03, 2011 9:35 AM
> To: aspectj-users@eclipse.org
> Subject: Re: [aspectj-users] Puzzling problem using AspectJ
>
> Hi,
>
> I see, that explains it, the [with runtime test] is a check to
> determine if you are in the cflow.
>
>> I am a little puzzled by what seem to be two calls to after(119 & 135).
>
> You have after advice, so it must intercept both the main exit paths
> (after returning) and any exception exit routes (after throwing).
>
> This one shows the call to the aspect prior to exiting via exception (athrow):
>
>> 119: invokevirtual #336; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.ajc$after$com_mycompany_myapp_aspects_tracing_myAspect$3$58016c43:()V
>> 122: aload 13
>> 124: athrow
>
> Are you positive the trace calls you are expecting to be augmented are
> in the cflow of the myop() pointcut?
>
> Also that wherever myop() is matching is accessible to be woven by
> AspectJ? It will need to insert code at where myop() matches to tag
> the subsequent flows as being 'in the cflow of myop()'. You could try
> something simple like a separate aspect:
>
> aspect Foo {
> before(): myop() {}
> }
>
> Check if that aspect weaves ok or if it complains that it cannot
> access something in order to weave it.
>
> cheers
> Andy
>
> On 31 May 2011 12:52, Abhijit Inamdar <ainam...@intrepidls.com> wrote:
>> Thanks for your response Andy.
>> This is not a singleton aspect. It is actually percflow(myop()) { ... where
>> myop() is another pointcut.
>>
>> Here is a snippet of the woven output around a log statement("Entering
>> isValidRequest" in this case):
>>
>> 76: invokestatic #367; //Method
>> org/aspectj/runtime/reflect/Factory.makeJP:(Lorg/aspectj/lang/JoinPoint$StaticPart;Ljava/lang/Object;Ljava/lang/Object;)Lorg/aspectj/lang/JoinPoint;
>> 79: getstatic #379; //Field
>> ajc$tjp_4:Lorg/aspectj/lang/JoinPoint$EnclosingStaticPart;
>> 82: invokevirtual #355; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.ajc$before$com_mycompany_myapp_aspects_tracing_myAspect$4$48864b4c:(Lorg/aspectj/lang/JoinPoint;Lorg/aspectj/lang/JoinPoint$StaticPart;)V
>> 85: getstatic #34; //Field logger:Lorg/apache/log4j/Logger;
>> 88: ldc #48; //String Entering isValidRequest
>> 90: invokestatic #331; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.hasAspect:()Z
>> 93: ifeq 102
>> 96: invokestatic #325; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.aspectOf:()Lcom/mycompany/myapp/aspects/tracing/myAspect;
>> 99: invokevirtual #328; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.ajc$before$com_mycompany_myapp_aspects_tracing_myAspect$2$58016c43:()V
>> 102: invokevirtual #50; //Method
>> org/apache/log4j/Logger.warn:(Ljava/lang/Object;)V
>> 105: goto 125
>> 108: astore 13
>> 110: invokestatic #331; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.hasAspect:()Z
>> 113: ifeq 122
>> 116: invokestatic #325; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.aspectOf:()Lcom/mycompany/myapp/aspects/tracing/myAspect;
>> 119: invokevirtual #336; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.ajc$after$com_mycompany_myapp_aspects_tracing_myAspect$3$58016c43:()V
>> 122: aload 13
>> 124: athrow
>> 125: nop
>> 126: invokestatic #331; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.hasAspect:()Z
>> 129: ifeq 138
>> 132: invokestatic #325; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.aspectOf:()Lcom/mycompany/myapp/aspects/tracing/myAspect;
>> 135: invokevirtual #336; //Method
>> com/mycompany/myapp/aspects/tracing/myAspect.ajc$after$com_mycompany_myapp_aspects_tracing_myAspect$3$58016c43:()V
>>
>>
>> I am a little puzzled by what seem to be two calls to after(119 & 135).
>>
>>
>>
>> ________________________________________
>> From: aspectj-users-boun...@eclipse.org [aspectj-users-boun...@eclipse.org]
>> on behalf of Andy Clement [andrew.clem...@gmail.com]
>> Sent: Monday, May 30, 2011 8:56 AM
>> To: aspectj-users@eclipse.org
>> Subject: Re: [aspectj-users] Puzzling problem using AspectJ
>>
>> Hi,
>>
>> So you are not loadtime weaving, you are just compile time weaving.
>> The weaveinfo messages indicate the bytecode is being modified. I
>> guess you could check the woven output from the compile and verify the
>> calls to the logger have been advised. Using 'javap -private
>> -verbose' against a class in the woven output you should see wherever
>> there is a call to getLogger there is a call to the advice?
>>
>> Actually, one thing does seem unusual. Is your pointcut definetly just this:
>>
>> call(* org.apache.log4j.Logger.*(..)) && !within(*..*Aspect);
>>
>> and in a singleton aspect?
>>
>> Because that can be fully statically matched, so I don't understand
>> why your weaveinfo message is suffixed with '[with runtime test]'. If
>> the runtime test (whatever it is) is failing it will not be running
>> your advice. If you want to post the snippet of bytecode around the
>> calls to getLogger we can check what the runtime test is.
>>
>> Andy
>>
>>
>> _______________________________________________
>> aspectj-users mailing list
>> aspectj-users@eclipse.org
>> https://dev.eclipse.org/mailman/listinfo/aspectj-users
>>
> _______________________________________________
> aspectj-users mailing list
> aspectj-users@eclipse.org
> https://dev.eclipse.org/mailman/listinfo/aspectj-users
> _______________________________________________
> aspectj-users mailing list
> aspectj-users@eclipse.org
> https://dev.eclipse.org/mailman/listinfo/aspectj-users
> _______________________________________________
> aspectj-users mailing list
> aspectj-users@eclipse.org
> https://dev.eclipse.org/mailman/listinfo/aspectj-users
>
_______________________________________________
aspectj-users mailing list
aspectj-users@eclipse.org
https://dev.eclipse.org/mailman/listinfo/aspectj-users
