Spring AOP Advice is being executed twice

Question

I am using Spring AOP to create an Aspect. The Aspect that I defined is being executed twice. I can't seem to figure out why. I'd appreciate any inputs anyone has on this issue.

Thanks!

// Spring Configuration

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
    xmlns:context="http://www.springframework.org/schema/context"
    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.0.xsd
    http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd
    http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-3.0.xsd"
    default-autowire="no"
    default-lazy-init="true">

    <bean id="loggingAdvice" class="com.xyz.aop.LoggingAdvice" />
    <aop:config>
        <aop:aspect id="loggingAspect" ref="loggingAdvice">
            <aop:pointcut id="loggingPointcut"
                expression="execution(* com.xyz.FooServiceImpl.foo(..))"/>
                <aop:around pointcut-ref="loggingPointcut" method="log" />
        </aop:aspect>
    </aop:config>

    <context:component-scan base-package="com.xyz.controllers" />

</beans>

// Advice

package com.xyz.aop;

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

public class LoggingAdvice {
    public Object log(final ProceedingJoinPoint pjp) throws Throwable {
        log.info("Started!");
        try {
            return pjp.proceed();
        } finally {
            log.info("Ended!");
        }
    }
}

// Advised Method

package com.xyz;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class FooServiceImpl implements FooService {
    private static final Log log = LogFactory.getLog(FooServiceImpl.class);

    @Override
    public void foo()  {
         log.info("Foo!");
        }
    }
}

// Output

   Started!
   Started!
   Foo!
   Ended!
   Ended!

// EDIT 1: Added more spring configuration info. Not using any Spring AOP annotations at all. I attached a debugger and saw that the aspect/log statements were being executed twice as well. So I doubt that it has anything to do with log statement printing the string twice.

If it is executed twice it is detected/applied twice. Make sure you don't also have @Aspect or other means of applying AOP. — M. Deinum
@M.Deinum: You could move your comment to an answer. I think it is correct. — kriegaex
Could you post more configuration? Is that your whole LoggingAdvice or are there some annotations missing, the same applies to the configuration I would suspect that there is more... — M. Deinum
Thanks so much for the reply, M. Deinum. I have posted more confugration. I do not have @Aspect annotations anywhere. I've checked and I do not see any other Spring AOP configuration elsewhere. I attached a debugger and found that control flows as follows: 1. log.info("Started!"); 2. pjp.proceed(); 3. log.info("Started!"); 4. pjp.proceed(); 5. log.info("Foo!"); 6. log.info("Ended!"); 7. log.info("Ended!") — user544192
Did you solved the problem? Could you post your logging configuration? — sven.kwiotek

Deepak Shingan Deepak Shingan · Accepted Answer · 2015-01-07T10:28:44

Well, it seems like this is actually an issue with the logger. Same problem I encountered long time back and found that everything is being logged twice. When I replaced logger calls with regular sysout calls, everything worked fine.

Spring AOP Advice is being executed twice

2 Answers