Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [aspectj-users] Puzzling problem using AspectJ

> Have you definetly confirmed the advice actually isn't being called?
Yes that seems to be the case. I ripped out the MDC stuff and put in plain logger calls(just like System.out) & also attached a debugger to the tomcat instance, but no luck in either case.

 > the 'duringMyOp()' is actually redundant here because all advice in a 'percflow(X)' aspect has the implicit additional condition ...<snip>
Thanks for the tip.  Please bear with my noobishness here.

>That would just be at one joinpoint though (if you see it once)
Actually I see it a bunch of times.  I'll try to see whether there is any correlation between the number of warnings and the number of logger calls.  I guess it shouldn't matter as we see the join points in the bytecode.

>Tricky to diagnose without a small failing sample.
The problem is that my small sample(i.e. my prototype) doesn't fail :(.  I'll continue plugging away at it making small diagnostic changes and see if I can come up with some interesting symptoms.

You help is really appreciated.  Have a great weekend.

Abhi

________________________________________
From: aspectj-users-bounces@xxxxxxxxxxx [aspectj-users-bounces@xxxxxxxxxxx] on behalf of Andy Clement [andrew.clement@xxxxxxxxx]
Sent: Friday, June 03, 2011 3:19 PM
To: aspectj-users@xxxxxxxxxxx
Subject: Re: [aspectj-users] Puzzling problem using AspectJ

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 <Ainamdar@xxxxxxxxxxxxxx> 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-bounces@xxxxxxxxxxx [aspectj-users-bounces@xxxxxxxxxxx] on behalf of Abhijit Inamdar [Ainamdar@xxxxxxxxxxxxxx]
> Sent: Friday, June 03, 2011 10:35 AM
> To: aspectj-users@xxxxxxxxxxx
> 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-bounces@xxxxxxxxxxx [aspectj-users-bounces@xxxxxxxxxxx] on behalf of Andy Clement [andrew.clement@xxxxxxxxx]
> Sent: Friday, June 03, 2011 9:35 AM
> To: aspectj-users@xxxxxxxxxxx
> 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 <Ainamdar@xxxxxxxxxxxxxx> 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-bounces@xxxxxxxxxxx [aspectj-users-bounces@xxxxxxxxxxx] on behalf of Andy Clement [andrew.clement@xxxxxxxxx]
>> Sent: Monday, May 30, 2011 8:56 AM
>> To: aspectj-users@xxxxxxxxxxx
>> 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@xxxxxxxxxxx
>> https://dev.eclipse.org/mailman/listinfo/aspectj-users
>>
> _______________________________________________
> aspectj-users mailing list
> aspectj-users@xxxxxxxxxxx
> https://dev.eclipse.org/mailman/listinfo/aspectj-users
> _______________________________________________
> aspectj-users mailing list
> aspectj-users@xxxxxxxxxxx
> https://dev.eclipse.org/mailman/listinfo/aspectj-users
> _______________________________________________
> aspectj-users mailing list
> aspectj-users@xxxxxxxxxxx
> https://dev.eclipse.org/mailman/listinfo/aspectj-users
>
_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users


Back to the top