RE: [aspectj-users] Aspect not being applied

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]

RE: [aspectj-users] Aspect not being applied

From: "Leyzerzon, Simeon " <simeon.leyzerzon@xxxxxxxx>
Date: Wed, 14 Oct 2009 13:42:51 -0400
Accept-language: en-US
Acceptlanguage: en-US
Delivered-to: aspectj-users@xxxxxxxxxxx
List-archive: <https://dev.eclipse.org/mailman/private/aspectj-users>
List-help: <mailto:aspectj-users-request@eclipse.org?subject=help>
List-subscribe: <https://dev.eclipse.org/mailman/listinfo/aspectj-users>, <mailto:aspectj-users-request@eclipse.org?subject=subscribe>
List-unsubscribe: <https://dev.eclipse.org/mailman/listinfo/aspectj-users>, <mailto:aspectj-users-request@eclipse.org?subject=unsubscribe>
Thread-index: AcpMSh7kovGDZSj5QhGOjXlqjYQnSQAmJjPQAAQh4QA=
Thread-topic: [aspectj-users] Aspect not being applied

I stand corrected on the behavior I described in my previous email. When I run the test, the ONLY time the aspect seems to be working is when Spring has interceptor is configured. Not sure why it generates 2 messages, but both are coming from Spring - one from a proxy and the other one from the interceptor itself, maybe something else needs to be added to Spring config:

2009-10-14 13:27:18,147 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW

2009-10-14 13:27:18,163 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]

2009-10-14 13:27:18,163 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled

2009-10-14 13:27:19,835 (MethodTimingInterceptor Line:41) Method Invocation [com.citi.gdos.iris.gma.dao.FooGmaDao.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 2(seconds) 1688(millis)

2009-10-14 13:27:19,835 (MethodTimingInterceptor Line:41) Method Invocation [$Proxy9.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 2(seconds) 1688(millis)

2009-10-14 13:27:19,850 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW

2009-10-14 13:27:19,850 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]

2009-10-14 13:27:19,850 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled

2009-10-14 13:27:20,147 (MethodTimingInterceptor Line:41) Method Invocation [com.citi.gdos.iris.gma.dao.FooGmaDao.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 0(seconds) 297(millis)

2009-10-14 13:27:20,147 (MethodTimingInterceptor Line:41) Method Invocation [$Proxy9.getExecutiveSummaryDatagridsDaoBuffer] Total Time: 0(seconds) 297(millis)

This is what is used in Spring config file:

<aop:config>

<aop:pointcut id="getAllDaoExPointcut"

_expression_="execution(* *..*Dao+.*(..))" />

<aop:advisor id="methodTimingAdvisor"

advice-ref="methodTimingAdvice" pointcut-ref="getAllDaoExPointcut" />

</aop:config>

So MethodProfilingAspect.java which I hoped would substitute the above interceptor doesn't work at all. This is the test run log:

2009-10-14 13:41:51,527 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW

2009-10-14 13:41:51,527 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]

2009-10-14 13:41:51,542 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled

2009-10-14 13:41:53,792 (ExecutiveSummaryGridCommonSP Line:50) SQL = P_ENTL_HC_ANLS_GET_SMRY_VW

2009-10-14 13:41:53,792 (ExecutiveSummaryGridCommonSP Line:156) Compiled stored procedure. Call string is [{call P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]

2009-10-14 13:41:53,792 (ExecutiveSummaryGridCommonSP Line:342) RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled

This is the aspect:

package com.citi.gdos.smart.applib.service.logging;

import java.math.BigDecimal;

import org.apache.commons.lang.time.DateUtils;
import org.apache.commons.lang.time.StopWatch;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;

/**
* @author sl81699
*
*/
@Aspect
public class MethodProfilingAspect {

private final static Log log = LogFactory.getLog(MethodProfilingAspect.class);

@Pointcut("execution(* *..*Dao+.*(..))")
    public void daoExecution(){}

@Around("daoExecution()")
public Object profile(ProceedingJoinPoint joinpoint) throws Throwable {

  final StopWatch stopWatch = new StopWatch();
  stopWatch.start();
  Object methodResult = null;
  try {
   methodResult = joinpoint.proceed();
  } finally {
   stopWatch.stop();
  }
  final long millis = stopWatch.getTime();
  final BigDecimal seconds = new BigDecimal(millis).divide(
    new BigDecimal(DateUtils.MILLIS_PER_SECOND),
    BigDecimal.ROUND_HALF_UP);

  if (log.isInfoEnabled()) {
   log.info("Method Invocation ["
     + joinpoint.getTarget().getClass().getName() + "."
     + joinpoint.getSignature().getName() + "] Total Time: "
     + seconds + "(seconds) " + millis + "(millis)");
  }
  return methodResult;
}

}

Thank you in advance for helping out with this!

Simeon

-----Original Message-----
From: aspectj-users-bounces@xxxxxxxxxxx [mailto:aspectj-users-bounces@xxxxxxxxxxx] On Behalf Of Leyzerzon, Simeon [ICG-IT]
Sent: Wednesday, October 14, 2009 11:44 AM
To: 'andrew@xxxxxxxxxxxx'; 'aspectj-users@xxxxxxxxxxx'
Subject: RE: [aspectj-users] Aspect not being applied

I looked deeper into it and here are some additional details:

1. I initially created the MethodProfilingAspect aspect via Eclipse wizard, so it gave it an .aj extension. That seemed to have prevented Eclipse from generating a Java class for the aspect. So I changed it into a .java file, now I can see the MethodProfilingAspect.class file when building.

2. I use compile time weaving, not LTW, so my script has a task:

                <iajc sourceRoots="./src" destDir="${dir.build}" source="${compile.source}" debug="${compile.debug}">
                        <classpath>
                                <path refid="classpath.base"/>
                                <path refid="classpath.aspect"/>
                        </classpath>
                </iajc>

Looks like now I see the log messages when running the test (compiling via Eclipse or via script, either way). But I can still see this warning in Eclipse, as before:

advice defined in com.citi.gdos.smart.applib.service.logging.MethodProfilingAspect has not been applied [Xlint:adviceDidNotMatch]

and consequently Eclipse's crossReference view doesn't work.

Here's this project's classpath:

<?xml version="1.0" encoding="UTF-8"?>
<classpath>
        <classpathentry kind="src" path="src"/>
        <classpathentry kind="src" path="test"/>
        <classpathentry kind="con" path="org.eclipse.jdt.launching.JRE_CONTAINER"/>
        <classpathentry kind="lib" path="/Repo/lib/spring.jar" sourcepath="I:/IRIS/Environment/Spring/spring-framework-2.5.6/src"/>
        <classpathentry kind="lib" path="/Repo/lib/aopalliance.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/commons-lang-2.4.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/commons-beanutils.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/commons-logging.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/iText-2.1.3.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/json_simple.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/json-lib-2.2.3-jdk13.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/json-taglib-0.1.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/log4j-1.2.8.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/poi-3.2.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/sftp.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/smjavaagentapi.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/smjavasdk2.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/spring-modules-cache.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/aspectjrt.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/commons-vfs-1.0.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/commons-collections-3.2.1.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/commons-net-2.0.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/jakarta-oro-2.0.8.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/httpclient-4.0.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/httpmime-4.0.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/jcifs-1.3.12.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/jsch-0.1.42.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/velocity-1.5.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/junit-4.4.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/spring-test.jar"/>
        <classpathentry kind="lib" path="/Repo/lib/weblogic.jar"/>
        <classpathentry kind="lib" path="/IrisApp/web/WEB-INF/classes"/>
        <classpathentry kind="lib" path="/Repo/lib/aspectjweaver.jar"/>
        <classpathentry kind="output" path="classes"/> </classpath>

Am I missing anything, or maybe some conflicting versions cause this behavior?
Please let me know what else I could do.

Thank you,
Simeon

-----Original Message-----
From: aspectj-users-bounces@xxxxxxxxxxx [mailto:aspectj-users-bounces@xxxxxxxxxxx] On Behalf Of Andrew Eisenberg
Sent: Tuesday, October 13, 2009 5:14 PM
To: aspectj-users@xxxxxxxxxxx
Subject: Re: [aspectj-users] Aspect not being applied

I am not sure, but the problem may have something to do with your aop.xml or your javaagent. I assume that you are using LTW, but if you are not, you may want to check that your aspect and in paths are properly configured.

Let me know if you continue to have a problem.

On Tue, Oct 13, 2009 at 11:16 AM, Leyzerzon, Simeon <simeon.leyzerzon@xxxxxxxx> wrote:
> In Eclipse I'm seeing the following warning:
>
> advice defined in
> com.xxxx.gdos.smart.applib.service.logging.MethodProfilingAspect has
> not been applied [Xlint:adviceDidNotMatch]
>
> for the following aspect:
>
>
> @Aspect
> public class MethodProfilingAspect {
>
>        private final static Log log =
> LogFactory.getLog(MethodProfilingAspect.class);
>
>        @Pointcut("execution(* *..*Dao+.*(..))")
>    public void daoExecution(){}
>
>        @Around("daoExecution()")
>        public Object profile(ProceedingJoinPoint joinpoint) throws
> Throwable {
>
>                final StopWatch stopWatch = new StopWatch();
>                stopWatch.start();
>                Object methodResult = null;
>                try {
>                        methodResult = joinpoint.proceed();
>                } finally {
>                        stopWatch.stop();
>                }
>                final long millis = stopWatch.getTime();
>                final BigDecimal seconds = new
> BigDecimal(millis).divide(
>                                new
> BigDecimal(DateUtils.MILLIS_PER_SECOND),
>                                BigDecimal.ROUND_HALF_UP);
>
>                if (log.isInfoEnabled()) {
>                        log.info("Method Invocation ["
>                                        + joinpoint.getTarget().getClass().getName() + "."
>                                        + joinpoint.getSignature().getName() + "] Total Time: "
>                                        + seconds + "(seconds) " +
> millis + "(millis)");
>                }
>                return methodResult;
>        }
>
> }
>
> and eventually the advise doesn't get applied, which is confirmed from this JUnit output:
>
> 2009-10-13 14:09:56,680 (ExecutiveSummaryGridCommonSP Line:50) SQL =
> P_ENTL_HC_ANLS_GET_SMRY_VW
> 2009-10-13 14:09:56,680 (ExecutiveSummaryGridCommonSP Line:156)
> Compiled stored procedure. Call string is [{call
> P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
> 2009-10-13 14:09:56,696 (ExecutiveSummaryGridCommonSP Line:342)
> RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
> 2009-10-13 14:10:00,477 (ExecutiveSummaryGridCommonSP Line:50) SQL =
> P_ENTL_HC_ANLS_GET_SMRY_VW
> 2009-10-13 14:10:00,477 (ExecutiveSummaryGridCommonSP Line:156)
> Compiled stored procedure. Call string is [{call
> P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
> 2009-10-13 14:10:00,477 (ExecutiveSummaryGridCommonSP Line:342)
> RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
>
> However, when configuring a similar advise via Spring, like so:
>
> <aop:config>
> <aop:pointcut id="getAllDaoExPointcut"
>        _expression_="execution(* *..*Dao+.*(..))" /> <aop:advisor
> id="methodTimingAdvisor"
> advice-ref="methodTimingAdvice" pointcut-ref="getAllDaoExPointcut" />
> </aop:config>
>
> <bean id="methodTimingAdvice"
> class="com.xxx.gdos.smart.applib.service.logging.MethodTimingIntercept
> or" />
>
>
> with the following advise:
>
> public class MethodTimingInterceptor implements MethodInterceptor {
>
>        private final static Log log =
> LogFactory.getLog(MethodTimingInterceptor.class);
>
>        public Object invoke(final MethodInvocation methodInvocation)
> throws Throwable {
>
>                final StopWatch stopWatch = new StopWatch();
>                stopWatch.start();
>                Object methodResult = null;
>                try {
>                        methodResult = methodInvocation.proceed();
>                } finally {
>                        stopWatch.stop();
>                }
>                final long millis = stopWatch.getTime();
>                final BigDecimal seconds = new
> BigDecimal(millis).divide(
>                                new
> BigDecimal(DateUtils.MILLIS_PER_SECOND),
>                                BigDecimal.ROUND_HALF_UP);
>
>                if (log.isInfoEnabled()) {
>                        log.info("Method Invocation ["
>                                        + methodInvocation.getThis().getClass().getName() + "."
>                                        + methodInvocation.getMethod().getName() + "] Total Time: "
>                                        + seconds + "(seconds) " +
> millis + "(millis)");
>                }
>                return methodResult;
>        }
> }
>
>
> I am seeing a different output from the same JUnit test reflect that the advise has been weaved in:
>
> 2009-10-13 14:11:58,770 (ExecutiveSummaryGridCommonSP Line:50) SQL =
> P_ENTL_HC_ANLS_GET_SMRY_VW
> 2009-10-13 14:11:58,786 (ExecutiveSummaryGridCommonSP Line:156)
> Compiled stored procedure. Call string is [{call
> P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
> 2009-10-13 14:11:58,786 (ExecutiveSummaryGridCommonSP Line:342)
> RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
> 2009-10-13 14:12:00,176 (MethodTimingInterceptor Line:41) Method
> Invocation
> [com.citi.gdos.iris.gma.dao.FooGmaDao.getExecutiveSummaryDatagridsDaoB
> uffer] Total Time: 1(seconds) 1422(millis)
> 2009-10-13 14:12:00,176 (MethodTimingInterceptor Line:41) Method
> Invocation [$Proxy9.getExecutiveSummaryDatagridsDaoBuffer] Total Time:
> 1(seconds) 1422(millis)
> 2009-10-13 14:12:00,176 (ExecutiveSummaryGridCommonSP Line:50) SQL =
> P_ENTL_HC_ANLS_GET_SMRY_VW
> 2009-10-13 14:12:00,176 (ExecutiveSummaryGridCommonSP Line:156)
> Compiled stored procedure. Call string is [{call
> P_ENTL_HC_ANLS_GET_SMRY_VW(?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]
> 2009-10-13 14:12:00,176 (ExecutiveSummaryGridCommonSP Line:342)
> RdbmsOperation with SQL [P_ENTL_HC_ANLS_GET_SMRY_VW] compiled
> 2009-10-13 14:12:00,317 (MethodTimingInterceptor Line:41) Method
> Invocation
> [com.citi.gdos.iris.gma.dao.FooGmaDao.getExecutiveSummaryDatagridsDaoB
> uffer] Total Time: 0(seconds) 141(millis)
> 2009-10-13 14:12:00,317 (MethodTimingInterceptor Line:41) Method
> Invocation [$Proxy9.getExecutiveSummaryDatagridsDaoBuffer] Total Time:
> 0(seconds) 141(millis)
>
> Could someone please point me to the right direction as to what is missing.
>
> TIA,
> Simeon
> _______________________________________________
> 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

References:
- RE: [aspectj-users] Aspect not being applied
  - From: Leyzerzon, Simeon

Prev by Date: RE: [aspectj-users] Aspect not being applied
Next by Date: Re: [aspectj-users] Before I forget
Previous by thread: RE: [aspectj-users] Aspect not being applied
Next by thread: [aspectj-users] Error message using java6 saying it must be 5 or above
Index(es):
- Date
- Thread

Breadcrumbs