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 and/or baeldung spring-aop blog post 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.
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface LogExecutionTime { }
Next, write the aspect which will get invoked everytime @LogExecutionTime is annotated on a method.
@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
@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
@Component
@RequiredArgsConstructor
public class Startup implements ApplicationListener<ApplicationReadyEvent> {
private final FlightService flightService;
@Override
public void onApplicationEvent(ApplicationReadyEvent event) {
this.flightService.getFlight();
}
}
@RequiredArgsConstructor annotation comes from Lombok
Now, once the application starts, we will see this being logged out
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.
@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.
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
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, 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 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.
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 which comes from @EnableAutoConfiguration configured within @SpringBootApplication annotation
Based on 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)
@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 which will lead us to this Github Issue #12196 and then to issue #12194 and lastly to issue #5423 which has the explanation of why it was configured as such. Do read it! There's also a stackoverflow 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
If you are using @EnableCaching annotation on non interface bean, you would to have explicitly set proxyTargetClass=true. See this commit
The change is stated in Spring Boot 2.0 Migration Guide
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 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.
Reference
Update
13 June 2022: Removed Use another annotation solution
