# Why Spring AOP don't work in Filter class # Introduction Aspect Oriented Programming (AOP) is a very powerful tool to learn, and is commonly used to solve cross-cutting concern such as Logging, Security, and Caching. If you are not familiar with `AOP`, I suggest reading up the [official docs](https://docs.spring.io/spring-framework/docs/current/reference/html/core.html#aop) and/or [baeldung spring-aop blog post](https://www.baeldung.com/spring-aop) before you continue. In this post, I will be sharing what I discovered and learned while implementing a simple logging mechanism through aspect using annotation-based (`@LogExecutionTime`) Pointcut expression. This includes the differences on how `Spring` and `Spring Boot` configures the default proxies that it uses (JDK and CGLIB) and how it affects the usage of such implementation. ## TLDR Based on my limited understanding, you can't apply `aspect` to `Filter` based class, at least when using `Spring AOP`. Read on to find out why is that so. # Spring AOP In this example, we want to log out the time taken to run a method which is a very common use case. Follow me through the post, and hopefully, like me, learn more about `Spring AOP` and what to expect. ## Demo First, we will create an annotation which will be used to annotate on the method, where our aspect will then target this annotation. ```java @Target(ElementType.METHOD) @Retention(RetentionPolicy.RUNTIME) public @interface LogExecutionTime { } ``` Next, write the aspect which will get invoked everytime `@LogExecutionTime` is annotated on a method. ```java @Slf4j @Aspect @Component public class LogExecutionTimeAspect { @Around("@annotation(LogExecutionTime)") public Object logTime(ProceedingJoinPoint joinPoint) throws Throwable { var stopWatch = new StopWatch(); stopWatch.start(); Object proceed = joinPoint.proceed(); stopWatch.stop(); log.info("{} took a total of {}ms to complete", joinPoint.getSignature(), stopWatch.getTotalTimeMillis()); return proceed; } } ``` > Did you know that `StopWatch` comes from `org.springframework.util` package? Then we create a service class, with a method that is being annotated with `@LogExecutionTime` ```java @Service public class FlightService { @LogExecutionTime public void getFlight() { try { Thread.sleep(1000); } catch (InterruptedException e) { e.printStackTrace(); } } } ``` Lastly, we will invoke `getFlight` method on `ApplicationReadyEvent` ```java @Component @RequiredArgsConstructor public class Startup implements ApplicationListener { private final FlightService flightService; @Override public void onApplicationEvent(ApplicationReadyEvent event) { this.flightService.getFlight(); } } ``` > `@RequiredArgsConstructor` annotation comes from [Lombok](https://projectlombok.org/features/constructor) Now, once the application starts, we will see this being logged out ```log void com.bwgjoseph.springbootaopwithfilters.FlightService.getFlight() took a total of 1023ms to complete ``` So far so good, right? You probably won't face any problem until you try to use it on `OncePerRequestFilter` class, or any class that violates the constraint of subclassing via `CGLIB Proxy`. ## Using on Filter class Let's imagine we have a `Filter` class, specifically, one that extends `OncePerRequestFilter`, and we want to log out execution time for `doFilterInternal` method. ```java @Slf4j @Component public class FlightFilter extends OncePerRequestFilter { @LogExecutionTime @Override protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException { log.info("{}", request); } } ``` Now, start up the application and you will run into this exception. ```log 022-06-11 20:11:59.236 INFO 15848 --- [ restartedMain] o.s.aop.framework.CglibAopProxy : Unable to proxy interface-implementing method [public final void org.springframework.web.filter.OncePerRequestFilter.doFilter(javax.servlet.ServletRequest,javax.servlet.ServletResponse,javax.servlet.FilterChain) throws javax.servlet.ServletException,java.io.IOException] because it is marked as final: Consider using interface-based JDK proxies instead! 2022-06-11 20:11:59.237 INFO 15848 --- [ restartedMain] o.s.aop.framework.CglibAopProxy : Unable to proxy interface-implementing method [public final void org.springframework.web.filter.GenericFilterBean.init(javax.servlet.FilterConfig) throws javax.servlet.ServletException] because it is marked as final: Consider using interface-based JDK proxies instead! 2022-06-11 20:11:59.288 ERROR 15848 --- [ restartedMain] o.a.c.c.C.[Tomcat-1].[localhost].[/] : Exception starting filter [flightFilter] java.lang.NullPointerException: Cannot invoke "org.apache.commons.logging.Log.isDebugEnabled()" because "this.logger" is null at org.springframework.web.filter.GenericFilterBean.init(GenericFilterBean.java:241) ~[spring-web-5.3.20.jar:5.3.20] // omitted 2022-06-11 20:11:59.299 ERROR 15848 --- [ restartedMain] o.apache.catalina.core.StandardContext : One or more Filters failed to start. Full details will be found in the appropriate container log file 2022-06-11 20:11:59.300 ERROR 15848 --- [ restartedMain] o.apache.catalina.core.StandardContext : Context [] startup failed due to previous errors2022-06-11 20:11:59.329 INFO 15848 --- [ restartedMain] o.apache.catalina.core.StandardService : Stopping service [Tomcat] 2022-06-11 20:11:59.338 WARN 15848 --- [ restartedMain] ConfigServletWebServerApplicationContext : Exception encountered during context initialization - cancelling refresh attempt: org.springframework.context.ApplicationContextException: Unable to start web server; nested exception is org.springframework.boot.web.server.WebServerException: Unable to start embedded Tomcat // omitted ``` ## Debugging Why is that so? What's happening? It wasn't obvious to me initially, until I take a closer look at the logs. Let's zoom into this particular line ```log 2022-06-11 20:11:59.236 INFO 15848 --- [ restartedMain] o.s.aop.framework.CglibAopProxy : Unable to proxy interface-implementing method [public final void org.springframework.web.filter.OncePerRequestFilter.doFilter(javax.servlet.ServletRequest,javax.servlet.ServletResponse,javax.servlet.FilterChain) throws javax.servlet.ServletException,java.io.IOException] because it is marked as final: Consider using interface-based JDK proxies instead! ``` But before we go further, let's try to understand a little on the key difference between `JDK Dynamic Proxy` and `CGLIB Proxy`. `JDK Dynamic Proxy` can only create proxy if the `target class` implements at least **1 interface** whereas `CGLIB Proxy` has no such limitation and is able to create proxy as long as the `target class / method` is **non-final**. This is important because it will help us understand why Spring AOP will not work on `OncePerRequestFilter` class. We know that Spring supports both [proxy mechanism](https://docs.spring.io/spring-framework/docs/current/reference/html/core.html#aop-introduction-proxies), but based on the docs, it states that it use `JDK Dynamic Proxy` by default. Wait a minute, if that is the case, why does the error message shows me `Consider using interface-based JDK proxies instead!`? This is where the difference between `Spring` and `Spring Boot` comes in. ## Findings Be patient with me here, as I bring you through my findings. These are what I have learned: - I came across [this article](https://www.springcloud.io/post/2022-01/springboot-aop/) which kind of explains the behavior between `Spring` and `Spring Boot` default proxy configuration. In summary, since `Spring Boot 2.0`, the default proxy was changed to `CGLIB` which does not follow `Spring Framework` defaults. ![image.png](https://cdn.hashnode.com/res/hashnode/image/upload/v1654952973537/NzdfqU-79.png align="left") From the image above, it shows that `@EnableAspectJAutoProxy` is indeed using `JDK Dynamic Proxy` since the default is configured as `false` ``` proxyTargetClass = false = JDK Dynamic Proxy proxyTargetClass = true = CGLIB Proxy ``` - In `Spring Boot`, there is no need to declare `@EnableAspectJAutoProxy` annotation because that is done for you in [AopAutoConfiguration.java](https://github.com/spring-projects/spring-boot/blob/main/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/aop/AopAutoConfiguration.java) which comes from `@EnableAutoConfiguration` configured within `@SpringBootApplication` annotation - Based on [AopAutoConfiguration.java](https://github.com/spring-projects/spring-boot/blob/main/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/aop/AopAutoConfiguration.java), we can see that this is how it defaults to `CGLIB` as the default as opposed to what we find out previously (in point 1) ```java @Configuration(proxyBeanMethods = false) @EnableAspectJAutoProxy(proxyTargetClass = true) @ConditionalOnProperty(prefix = "spring.aop", name = "proxy-target-class", havingValue = "true", matchIfMissing = true) static class CglibAutoProxyConfiguration { } ``` When `spring.aop.proxy-target-class` is not defined, it will be default to `true`, and true means using `CGLIB Proxy` We can set `spring.aop.proxy-target-class=false` in `application.properties` to override the default behavior in `Spring Boot` - Tracing the history of the commit for `AopAutoConfiguration`, in particular, this [commit](https://github.com/spring-projects/spring-boot/commit/782ab2803e05269b651480d99f071bfed45bd5e9) which will lead us to this [Github Issue #12196](https://github.com/spring-projects/spring-boot/issues/12196) and then to [issue #12194](https://github.com/spring-projects/spring-boot/issues/12194) and lastly to [issue #5423](https://github.com/spring-projects/spring-boot/issues/5423) which has the explanation of why it was configured as such. Do read it! There's also a [stackoverflow](https://stackoverflow.com/questions/54980004/why-choose-cglib-proxying-as-the-default-after-springboot-2-0) question on it. - Based on my understanding, the reason for the change was because of `@Transactional` annotation so that classes that did not implement `interface` but annotated with `@Transactional` would still work regardless. See this [commit](https://github.com/spring-projects/spring-boot/commit/47fb614bde670f3ebf113334c4b70822c1a33232) - If you are using `@EnableCaching` annotation on non interface bean, you would to have explicitly set `proxyTargetClass=true`. See this [commit](https://github.com/spring-projects/spring-boot/commit/99dae09f84b9ec85d21c83f0ccc2fcb45d17ea28) - The change is stated in [Spring Boot 2.0 Migration Guide](https://github.com/spring-projects/spring-boot/wiki/Spring-Boot-2.0-Migration-Guide#default-proxying-strategy) - If you configure default to `JDK Dynamic Proxy`, it will use it, and also try to use `CGLIB Proxy` if possible. However, if you [configure](https://github.com/spring-projects/spring-boot/issues/8434#issuecomment-287356778) the default to use `CGLIB Proxy`, it will not attempt to use `JDK Dynamic Proxy`, so all subclasses are create only via `CGLIB Proxy`. [Please correct me if I'm wrong here] What does that leave us? Nothing, actually. For average users, you won't even notice this at all, unless you are applying aspect on areas where you can't, which will then cause you to face the error like above. But in my case, I wanted to use the `aspect` on the `Filter` class. So let's see if there's any way to resolve the error, and then apply the `aspect`. ## Solution Unfortunately, unless I explore on the usage of `AspectJ` instead of `Spring AOP`, it doesn't seem like I am able to apply the `aspect` onto `Filter` class due to the various limitation. So what we can do is to apply workaround, so that our application can run as per normal. ### Use JDK Dynamic Proxy as default Switch to use `JDK Dynamic Proxy` as the default by specifying this in `application.properties` which means fallback to what `Spring Framework` does in the first place. But take note of the downside to this, for dependency injection, you have to ensure you injected via the interface, and not the concrete class. ``` spring.aop.proxy-target-class=false ``` After adding the config, the application would start and run as usual but the aspect will still not be applied and run. Note that even after we switch to use `JDK Dynamic Proxy` as the default, it doesn't mean classes will be proxied via `JDK Dynamic Proxy`. The same rule will still applies where - if the class implements a interface, `JDK Dynamic Proxy` will apply - if the class does not, `CGLIB Proxy` will apply - if the class or method is final, `CGLIB Proxy` will **not** apply I will blog about this more in the next blog post. ### Use AspectJ Spring AOP only provides partial AOP solution whereas AspectJ is a complete AOP solution. I am not familiar with AspectJ, having not used it before, but I supposed that the same limitation for Spring AOP would not be imposed onto AspectJ. # Conclusion We look at how we use `Spring AOP` to log out the execution time for a method call, and how it fails to work when used at `OncePerRequestFilter` class due to the (`doFilterInternal`) method declared as `final` which is the limitation for `CGLIB Proxy`. Then we look at the the difference between `JDK Dynamic Proxy` and `CGLIB Proxy`, and how both `Spring` and `Spring Boot` configures the default. Lastly, how we can workaround the problem by switching to use `JDK Dynamic Proxy` as the default or using `AspectJ` as opposed to `Spring AOP` to possibly allow the use of `aspect` in `Filter` class. Having read many resources, and spend more time trying to understand how the proxy works, it also helped me gain more insights like why internal method calls does not work for proxy based class (although there are workaround). There are still some concept that I don't quite grasp entirely, but that's okay. With my new knowledge gained, I believe it will help me understand some other related concept around AOP much easier. # Source Code As usual, full source code is available in [GitHub](https://github.com/bwgjoseph/tutorials/tree/main/spring-boot-aop-with-filters). # Reference - [spring-core-aop](https://docs.spring.io/spring-framework/docs/current/reference/html/core.html#aop) - [spring-aop-vs-aspectj](https://www.baeldung.com/spring-aop-vs-aspectj) - [springboot-aop](https://www.springcloud.io/post/2022-01/springboot-aop/) - [what-is-the-difference-between-jdk-dynamic-proxy-and-cglib](https://stackoverflow.com/questions/10664182/what-is-the-difference-between-jdk-dynamic-proxy-and-cglib) - [spring-aop-works-without-enableaspectjautoproxy](https://stackoverflow.com/questions/48625149/spring-aop-works-without-enableaspectjautoproxy) - [spring-aop-pointcuts-designators](https://docs.spring.io/spring-framework/docs/current/reference/html/core.html#aop-pointcuts-designators) - [transactions-caching-and-aop-understanding-proxy-usage-in-spring](https://spring.io/blog/2012/05/23/transactions-caching-and-aop-understanding-proxy-usage-in-spring) # Update 13 June 2022: Removed `Use another annotation` solution