0

I want to create an aspectJ component within springboot project, that prints log messages wherever @Loggable annotation is present, methods or class, or maybe both (method will be considered).

Loggable annotation:

@Documented
@Retention(RetentionPolicy.RUNTIME)
@Target({ ElementType.TYPE, ElementType.METHOD })
public @interface Loggable {
   boolean duration() default false;
}

Aspectj class:

@Aspect
@Component
public class LogInterceptorAspect {

   @Pointcut("execution(public * ((@Loggable *)+).*(..)) && within(@Loggable *)")
   public boolean loggableDefinition(Loggable loggable) {
      return loggable.duration();
   }

   @Around("loggableDefinition(withDuration)")
   public void log(ProceedingJoinPoint joinPoint, boolean withDuration) throws Throwable {
      getLogger(joinPoint).info("start {}", joinPoint.getSignature().getName());

      StopWatch sw = new StopWatch();
      Object returnVal = null;
      try {
         sw.start();
         returnVal = joinPoint.proceed();
      } finally {
         sw.stop();
      }

      getLogger(joinPoint).info("return value: {}, duration: {}", returnVal, sw.getTotalTimeMillis()));

   }

   private Logger getLogger(JoinPoint joinPoint) {
      return LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
   }
}

With the above code I get

java.lang.IllegalArgumentException: error at ::0 formal unbound in pointcut

What's wrong?

Idan
  • 201
  • 3
  • 5
  • sorry, I have changed the title. thanks – Idan Dec 17 '16 at 12:49
  • see this post for an alternate method for implementing: http://stackoverflow.com/questions/17481183/aspectj-class-level-annotation-advice-with-annotation-as-method-argument – Bob Lukens Dec 17 '16 at 19:00

1 Answers1

1

Basically the formal parameter is unbound on the PointCut.

Here is an alternate working example based on the approach detailed in this post: @AspectJ Class level Annotation Advice with Annotation as method argument

I modified your approach slightly to avoid the problem for a couple of reasons :

  • simplified the initial PointCut and gave it a single responsibility

    • gave it a descriptive name indicating its purpose
    • made it more reusable by removing the dependency on Loggable
    • kept it close in implementation to most of the sample documentation available
  • broke the Advice into two simpler methods each with a single responsibility that is easy to comprehend

    • simplified the expressions by removing fancy operators
    • injected the annotation directly into the Advice where its used rather than attempting to pass from the PointCut which feels like an unnecessary complexity
    • kept it close in implementation to most of the sample documentation available
  • added the start of a unit test to verify the expected behavior so that changes can be made responsibly to the PointCut and Advice expressions (you should complete it)

When working with PointCut/Advice Expressions, I generally try to go for the simplest, clearest solutions possible and unit test them thoroughly to ensure the behavior I expect is what I get. The next person to look at your code will appreciate it.

Hope this helps.

package com.spring.aspects;

import static org.junit.Assert.assertEquals;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringRunner;
import org.springframework.util.StopWatch;

import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@RunWith(SpringRunner.class)
@ContextConfiguration(classes = AspectInjectAnnotationTest.TestContext.class)
public class AspectInjectAnnotationTest {

    @Documented
    @Retention(RetentionPolicy.RUNTIME)
    @Target({ ElementType.TYPE, ElementType.METHOD })
    public @interface Loggable {
        boolean duration() default false;
    }

    @Aspect
    public static class LogInterceptorAspect {

        @Pointcut("execution(public * *(..))")
        public void anyPublicMethod() {
        }

        @Around("anyPublicMethod() && @annotation(loggable)")
        public Object aroundLoggableMethods(ProceedingJoinPoint joinPoint, Loggable loggable) throws Throwable {
            return log(joinPoint, loggable);
        }

        @Around("(anyPublicMethod() && !@annotation(AspectInjectAnnotationTest.Loggable)) && @within(loggable)")
        public Object aroundPublicMethodsOnLoggableClasses(ProceedingJoinPoint joinPoint, Loggable loggable)
                throws Throwable {
            return log(joinPoint, loggable);
        }

        public Object log(ProceedingJoinPoint joinPoint, Loggable loggable) throws Throwable {
            getLogger(joinPoint).info("start [{}], duration [{}]", joinPoint.getSignature().getName(),
                    loggable.duration());

            StopWatch sw = new StopWatch();
            Object returnVal = null;
            try {
                sw.start();
                returnVal = joinPoint.proceed();
            } finally {
                sw.stop();
            }

            getLogger(joinPoint).info("return value: [{}], duration: [{}]", returnVal, sw.getTotalTimeMillis());

            return returnVal;
        }

        private Logger getLogger(JoinPoint joinPoint) {
            return LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
        }
    }

    // class level annotation - should only proxy public methods
    @Loggable(duration = true)
    public static class Service1 {

        // public - should be proxied
        public String testS1M1(String test) {
            return testProtectedM(test);
        }

        // public - should be proxied
        public String testS1M2(String test) {
            return testProtectedM(test);
        }

        // protected - should not be proxied
        protected String testProtectedM(String test) {
            return testPrivateM(test);
        }

        // private - should not be proxied
        private String testPrivateM(String test) {
            return test;
        }
    }

    // no annotation - class uses method level
    public static class Service2 {

        @Loggable
        public String testS2M1(String test) {
            return protectedMethod(test);
        }

        // no annotation - should not be proxied
        public String testS2M2(String test) {
            return protectedMethod(test);
        }

        // protected - should not be proxied
        protected String protectedMethod(String test) {
            return testPrivate(test);
        }

        // private - should not be proxied
        private String testPrivate(String test) {
            return test;
        }
    }

    // annotation - class and method level - make sure only call once
    @Loggable
    public static class Service3 {

        @Loggable
        public String testS3M1(String test) {
            return test;
        }
    }

    // context configuration for the test class
    @Configuration
    @EnableAspectJAutoProxy
    public static class TestContext {

        // configure the aspect
        @Bean
        public LogInterceptorAspect loggingAspect() {
            return new LogInterceptorAspect();
        }

        // configure a proxied beans
        @Bean
        public Service1 service1() {
            return new Service1();
        }

        // configure a proxied bean
        @Bean
        public Service2 service2() {
            return new Service2();
        }

        // configure a proxied bean
        @Bean
        public Service3 service3() {
            return new Service3();
        }
    }

    @Autowired
    private Service1 service1;

    @Autowired
    private Service2 service2;

    @Autowired
    private Service3 service3;

    @Test
    public void aspectShouldLogAsExpected() {
        // observe the output in the log, but craft this into specific
        // unit tests to assert the behavior you are expecting.

        assertEquals("service-1-method-1", service1.testS1M1("service-1-method-1")); // expect logging
        assertEquals("service-1-method-2", service1.testS1M2("service-1-method-2")); // expect logging
        assertEquals("service-2-method-1", service2.testS2M1("service-2-method-1")); // expect logging
        assertEquals("service-2-method-2", service2.testS2M2("service-2-method-2")); // expect no logging
        assertEquals("service-3-method-1", service3.testS3M1("service-3-method-1")); // expect logging once


    }
}
Community
  • 1
  • 1
Bob Lukens
  • 700
  • 6
  • 10
  • see that both aroundLoggableMethods & aroundPublicMethodsOnLoggableClasses are called if Loggable is present in class and method – Idan Dec 18 '16 at 09:57
  • try something like this to prevent duplicate calls when both class and method are annotated: `@Around("(anyPublicMethod() && !@annotation(AspectTest.Loggable)) && @within(loggable)") public void aroundPublicMethodsOnLoggableClasses(ProceedingJoinPoint joinPoint, Loggable loggable) ` – Bob Lukens Dec 18 '16 at 12:32
  • It is nice that you present a working solution, but maybe you should also have explained why the OP's version throws `formal unbound in pointcut`: because the pointcut signutare sports a method parameter which has not been bound via `args()`, `this()`, `target()`, `@annotation()` or similar. I think the OP should also understand *_why_* your solution looks different from his. – kriegaex Dec 18 '16 at 12:42
  • I updated the answer to be more complete. thanks for indicating that it was a little lacking in details – Bob Lukens Dec 18 '16 at 15:03
  • also note - since you are doing performance logging only you might want to look at using Spring's JamonPerformanceMonitorInterceptor or PerformanceMonitorInterceptor to see if you can get the same functionality without having to write any code – Bob Lukens Dec 18 '16 at 23:59