Spring 3 AOP Schema-based implementation

[brethodgson]

I have been experimenting with introducing AOP into our Spring/Surf web application for profiling use. I've scoured the forums and official documentation and it looks like I've done everything right. I can't figure out why my profiling aspect doesn't log execution time. I did get this to work through annotations, but given that I want the ability to enable/disable pointcut definitions as needed, I went the schema route. The application builds and starts up just fine, but when I hit the service I get no output.

Here is my config.xml

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xmlns:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="http://www.springframework.org/schema/beans
                           http://www.springframework.org/schema/beans/spring-beans-3.1.xsd
                           http://www.springframework.org/schema/aop 
                           http://www.springframework.org/schema/aop/spring-aop-3.1.xsd">
  
  <bean id="shopProfiler" class="com.xxxx.business.profiler.ShopProfiler"/>
  
  <aop:config proxy-target-class="true">
    <aop:aspect id="shopServicesProfiler" ref="shopProfiler">
      <aop:pointcut id="shopServices" expression="execution(* com.xxxx.service.*.*(..))"/>
      <aop:around method="logMethodTiming" pointcut-ref="shopServices"/>
    </aop:aspect>
  </aop:config>
  
</beans>

Here is my ShopProfiler.java class

package com.xxxx.business.profiler;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.ProceedingJoinPoint;

public class ShopProfiler {
	
	protected final Log logger = LogFactory.getLog(ShopProfiler.class);
	
    public Object logMethodTiming(ProceedingJoinPoint pjp) throws Throwable {
            long start = System.currentTimeMillis();
            Object output = pjp.proceed();
            long elapsedTime = System.currentTimeMillis() - start;
            logger.debug(pjp.getSignature().getName() + " execution time: " + elapsedTime + " milliseconds.");
            return output;
    }
}

I have the following AOP dependencies:

<dependency>
  <groupId>org.springframework</groupId>
  <artifactId>spring-aop</artifactId>
  <version>3.1.0.RELEASE</version>
</dependency>
<dependency>
  <groupId>org.aspectj</groupId>
  <artifactId>aspectjweaver</artifactId>
  <version>1.7.0.RELEASE</version>
</dependency>

And for good measure I'll include the service that I wish to profile

package com.xxxx.service.ecommerce;

import javax.servlet.http.HttpServletRequest;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.ResponseBody;

import com.xxxx.service.ecommerce.response.ServiceResponse;

@Controller
@RequestMapping("/cart")
public class CartService extends BaseService {

    protected final Log logger = LogFactory.getLog(getClass());


    /**
     * Handles a request to apply a coupon code to an existing cart.
     *
     * @return A response indicating whether the coupon code was applied to the
     *      cart successfully or not.
     */
	@RequestMapping(value="/coupon", method=RequestMethod.GET)
	public @ResponseBody ServiceResponse handleCouponCode(
            HttpServletRequest request, @RequestParam(required=true) String couponCode) {
		
	// Gets an initialized response
        ServiceResponse response = getServiceResponse(request);
        
        //
        //alter the response
        //
        
        return response;
    }
}