Affects: Spring Boot 2.5.6 (Both AOP and Web are 2.5.6)
Greetings,
I'm relatively new to Spring, but after a bit of Googling this seems like an issue with interconnection between different Spring components. Or maybe I'm just using them wrong? Please advise if so, otherwise this just might be an unfortunate bug?
I'm trying to add a traceId entry to our logs via MDC.
I've created a filter that extends OncePerRequestFilter which doesn't really do anything, except serves as a place to attach an advice to.
@Component
class TraceIdFilter : OncePerRequestFilter() {
@Traceable
override fun doFilterInternal(
request: HttpServletRequest,
response: HttpServletResponse,
filterChain: FilterChain
) {
filterChain.doFilter(request, response)
}
}
I have an @Around advice:
@Aspect
@Component
class TraceableRequestAspect(private val uuid: () -> UUID) {
@Around("@annotation(Traceable)")
fun advice(joinPoint: ProceedingJoinPoint) {
try {
MDC.put(LogstashField.TRACE_ID, "${uuid()}")
joinPoint.proceed()
} finally {
MDC.remove(LogstashField.TRACE_ID)
}
}
}
I expect that the Around advice will 'wrap' the filter method and attach an MDC entry to all HTTP request logs and then clean up after itself.
In reality, this is what I'm seeing:
2022-01-20 14:42:54.147 INFO 23739 --- [ main] 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-01-20 14:42:54.147 INFO 23739 --- [ main] 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-01-20 14:42:54.211 ERROR 23739 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Exception starting filter [traceIdFilter]
java.lang.NullPointerException: null
at org.springframework.web.filter.GenericFilterBean.init(GenericFilterBean.java:241)
at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:270)
at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:105)
at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4613)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5256)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1396)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1386)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:919)
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:835)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1396)
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1386)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75)
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140)
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:919)
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:263)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:432)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:927)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183)
at org.apache.catalina.startup.Tomcat.start(Tomcat.java:486)
at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.initialize(TomcatWebServer.java:123)
at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.<init>(TomcatWebServer.java:104)
at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getTomcatWebServer(TomcatServletWebServerFactory.java:450)
at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getWebServer(TomcatServletWebServerFactory.java:199)
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.createWebServer(ServletWebServerApplicationContext.java:182)
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.onRefresh(ServletWebServerApplicationContext.java:160)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:577)
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145)
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754)
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:338)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332)
at net.leoncorp.ft.integration.ApplicationKt.main(Application.kt:14)
2022-01-20 14:42:54.212 ERROR 23739 --- [ main] o.apache.catalina.core.StandardContext : One or more Filters failed to start. Full details will be found in the appropriate container log file
2022-01-20 14:42:54.212 ERROR 23739 --- [ main] o.apache.catalina.core.StandardContext : Context [] startup failed due to previous errors
2022-01-20 14:42:54.254 INFO 23739 --- [ main] o.apache.catalina.core.StandardService : Stopping service [Tomcat]
I'm not sure whether I can follow the advice the error message throws as none of the code responsible for this is under my purview.
Thanks in advance for any assistance.
Comment From: sbrannen
Please provide a minimal example application that demonstrates the behavior you have described -- preferably written in Java instead of Kotlin and available via a public Git repository or a ZIP file that we can download and run.
Comment From: nexsja
@sbrannen not sure if I'm 100% correct on this, but here it is: https://github.com/nexsja/aspect-filter-issue
I get the same error when trying to boot the application.
2022-01-20 18:06:01.795 INFO 25512 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2022-01-20 18:06:01.796 INFO 25512 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.50]
2022-01-20 18:06:01.870 INFO 25512 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2022-01-20 18:06:01.871 INFO 25512 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1180 ms
2022-01-20 18:06:01.884 INFO 25512 --- [ main] 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-01-20 18:06:01.884 INFO 25512 --- [ main] 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-01-20 18:06:01.944 ERROR 25512 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Exception starting filter [traceIdFilter]
java.lang.NullPointerException: null
at org.springframework.web.filter.GenericFilterBean.init(GenericFilterBean.java:241) ~[spring-web-5.3.9.jar:5.3.9]
at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:271) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:106) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4613) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5256) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1388) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[na:na]
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:921) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:835) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1388) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[na:na]
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:921) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:263) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:437) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:934) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.startup.Tomcat.start(Tomcat.java:486) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.initialize(TomcatWebServer.java:123) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.<init>(TomcatWebServer.java:104) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getTomcatWebServer(TomcatServletWebServerFactory.java:450) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getWebServer(TomcatServletWebServerFactory.java:199) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.createWebServer(ServletWebServerApplicationContext.java:182) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.onRefresh(ServletWebServerApplicationContext.java:160) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:577) ~[spring-context-5.3.9.jar:5.3.9]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:338) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.3.jar:2.5.3]
at com.example.aspectfilterissue.AspectFilterIssueApplication.main(AspectFilterIssueApplication.java:10) ~[main/:na]
2022-01-20 18:06:01.945 ERROR 25512 --- [ main] o.apache.catalina.core.StandardContext : One or more Filters failed to start. Full details will be found in the appropriate container log file
2022-01-20 18:06:01.945 ERROR 25512 --- [ main] o.apache.catalina.core.StandardContext : Context [] startup failed due to previous errors
2022-01-20 18:06:01.991 INFO 25512 --- [ main] o.apache.catalina.core.StandardService : Stopping service [Tomcat]
2022-01-20 18:06:02.000 WARN 25512 --- [ main] 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
2022-01-20 18:06:02.010 INFO 25512 --- [ main] ConditionEvaluationReportLoggingListener :
Error starting ApplicationContext. To display the conditions report re-run your application with 'debug' enabled.
2022-01-20 18:06:02.033 ERROR 25512 --- [ main] o.s.boot.SpringApplication : Application run failed
Comment From: mdeinum
Your @Around aspect is written not entirely correct. You always must return the result of joinpoint.proceed() and the return type must be Object not void. If you don't you will be actually destroying the result of the method execution and always return null.
You aren't the first to run into this, I've answered many questions on stack overflow on this. It might be worthwhile to improve the documentation on this that that is a must.
Comment From: nexsja
@mdeinum thanks for taking the time and looking into this. :)
While I agree that the docs might be improved in regards to the return values, unfortunately it doesn't solve the issue at hand. I've updated the repository I've linked above with your suggestion and the problem still persists.
Comment From: mdeinum
Running the code with a recent JDK shows the following error (hooray for the useful NullPointerExceptions):
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.9.jar:5.3.9]
at org.apache.catalina.core.ApplicationFilterConfig.initFilter(ApplicationFilterConfig.java:271) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:106) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:4613) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5256) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1388) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na]
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:145) ~[na:na]
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:921) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:835) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1398) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1388) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.FutureTask.run$$$capture(FutureTask.java:264) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java) ~[na:na]
at org.apache.tomcat.util.threads.InlineExecutorService.execute(InlineExecutorService.java:75) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:145) ~[na:na]
at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:921) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardEngine.startInternal(StandardEngine.java:263) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardService.startInternal(StandardService.java:437) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.core.StandardServer.startInternal(StandardServer.java:934) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.apache.catalina.startup.Tomcat.start(Tomcat.java:486) ~[tomcat-embed-core-9.0.50.jar:9.0.50]
at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.initialize(TomcatWebServer.java:123) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.<init>(TomcatWebServer.java:104) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getTomcatWebServer(TomcatServletWebServerFactory.java:450) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getWebServer(TomcatServletWebServerFactory.java:199) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.createWebServer(ServletWebServerApplicationContext.java:182) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.onRefresh(ServletWebServerApplicationContext.java:160) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:577) ~[spring-context-5.3.9.jar:5.3.9]
at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:338) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343) ~[spring-boot-2.5.3.jar:2.5.3]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332) ~[spring-boot-2.5.3.jar:2.5.3]
at com.example.aspectfilterissue.AspectFilterIssueApplication.main(AspectFilterIssueApplication.java:10) ~[main/:na]
Due to a proxy the fields are null, as the init method is final it cannot be proxied. It is called on the proxy, instead of passed through to the wrapped filter. Leading to this issue.
That being said even if this error wouldn't occur the aspect wouldn't kick in, as the doFilterInternal is called internally and not through a proxy.
Comment From: nexsja
So what you're saying is that it's impossible to attach an aspect to doFilterInternal?
I'm not sure I'm understanding you correctly. Is this a bug or it's expected behaviour when doing something you shouldn't be doing in the first place? 😆
Comment From: mdeinum
It is expected behavior due to the nature of proxies being used for AOP (it would work when using load or compile time weaving).
Next to that I probably wouldn't do this in an aspect but rather implement a filter which sets the trace id (and use an aspect for things like services etc.).
Nonetheless this isn't the first time I'm looking into issues/questions regarding proxies with final methods leading to surprising results. So this might need to be given some attention in documentation or logging.
Comment From: sbrannen
It is expected behavior due to the nature of proxies being used for AOP (it would work when using load or compile time weaving).
Next to that I probably wouldn't do this in an aspect but rather implement a filter which sets the trace id (and use an aspect for things like services etc.).
Thanks for taking the time to triage this issue for the team, @mdeinum! 👍
I agree with Marten's assessment as well as his advice.
If your goal is only to include a trace ID in your log statements via MDC, implementing a Filter that does exactly that would greatly simplify matters. In other words, the use of an aspect is unnecessary for this use case.
Another approach is to implement a custom HandlerInterceptor.
A quick search on the Internet revealed that this blog actually demonstrates examples of both approaches.
In light of that, I am closing this issue.
Comment From: sbrannen
Your
@Aroundaspect is written not entirely correct. You always must return the result ofjoinpoint.proceed()and the return type must beObjectnotvoid. If you don't you will be actually destroying the result of the method execution and always returnnull.You aren't the first to run into this, I've answered many questions on stack overflow on this. It might be worthwhile to improve the documentation on this that that is a must.
I opened #27980 to address this.
Comment From: kriegaex
For reference: This question has been asked again lately on Stack Overflow, and here is my answer explaining the situation in more detail, also linking back to @mdeinum's reply here. The more general issue with trying to advise final methods accessing instance fields is explained here. My answer on SO also contains sample pointcuts for users who want to do advise filters using native AspectJ.