Spring AOP - CustomizableTraceInterceptor
in Blog
Immediate, automated insights into your application.
The more I learn about Spring, the more I come to understand and appreciate its true power, with one major appeal being developer productivity.
In my previous post I discussed some useful things we can do with aspect oriented programming, including logging. Spring covers many of these use cases out of the box, without any additional concepts or dependencies. Let’s explore how to configure a trace interceptor and how this can make us more productive.
Oftentimes, when we encounter a bug in the live application, we want to get a deeper understanding of what lead to the current state and turn to the logs. Now, during development we may not have decided upon and set up detailed logging, which leads us to add some additional logging or print statements to get insights into the erroneous process.
This costs time, is annoying, and is ultimately not a very lean process, as a better alternative is available. The premise is the following:
Automatically provide meaningful insights into the app. Configure once, applied seamlessly to any existing or new code without additional work.
Say you implement a new part of your app, including a service with one central method:
@Service
class TestService {
fun testMultiply(x: Int, y: Int): Int {
Thread.sleep(250)
println("TEST!")
return x * y
}
}
Now, during testing it turns out there is a bug which leads to inconsistent results, even though you are sure the input params are as expected.
Wouldn’t it be nice to have the following in your logs:
2020-09-27 13:32:51.404 TRACE 2220 --- [Test worker] m.a.y.s.TestService: Entering testMultiply(6,7)
TEST!
2020-09-27 13:32:51.654 TRACE 2220 --- [Test worker] m.a.y.s.TestService: Leaving testMultiply(), returned 42, running time = 250 ms
This includes a message on entering and leaving the method, with information about the parameters, the return value and the time spent. This can be customized further, but is usually a good starting point.
Logger configuration
Here is the corresponding logger configuration. Source available here.
@Configuration
class LoggerConfig {
@Bean fun customizableTraceInterceptor() = CustomizableTraceInterceptor().apply {
setUseDynamicLogger(true)
setEnterMessage("Entering $[methodName]($[arguments])")
setExitMessage("Leaving $[methodName](), returned $[returnValue], running time = $[invocationTime] ms")
setExceptionMessage("Error $[methodName](), exception $[exception], running time = $[invocationTime] ms")
}
@Bean fun loggingAdvisor(): Advisor {
val pointcut = AspectJExpressionPointcut().apply {
expression = """
execution (* (@org.springframework.stereotype.Service *).*(..))
|| execution (* (@org.springframework.stereotype.Component *).*(..))
""".trimIndent()
}
return DefaultPointcutAdvisor(pointcut, customizableTraceInterceptor())
}
}
The details of the pointcut expression depend on what classes you want to target. I just wanted to know about all services and components.
Notice that we do not need any explicit Spring AOP dependency or any other application configuration. The entire trace logging is self-contained and can be deployed from day one. You can copy-paste this class, and it works immediately.
By default, the traces are logged as trace, so set the logging level accordingly. My application.yml contains the following during development, where the last part is my root package name.
logging:
level:
me.avo.yunyin: TRACE
Conclusion
No, or greatly reduced need to write debug statements! Thanks to proxying, your code stays clean, whilst Spring works its magic.
For production use, you will of course have to adapt your logging, but during development this is value for no money.
I will experiment further to see how far I can push this, but this will definitely be a part of every future app I work on.
