Logging is a cross-cutting concern and therefore AOP comes on. With Spring Boot it is quite easy to make AOP work and configure different aspects. Here, I will concentrate on a logger aspect that logs the entry and exit of a method call. Additionally, the execution time is logged as well.
First, we need to clarify some terminology that comes with AOP:
- aspect: Class containing cross-cutting concern
- adivice: Job of an aspect
- join point: possible point in the application where an aspect can be applied
- pointcut: defines where an aspect is applied
- weaving: process of applying aspects to a target object
Spring AOP aspects are woven in during runtime, i.e. during the execution of the application. AspectJ allows to weave in aspects during compile time.
Runtime weaving with Spring AOP is based on proxy usage and thus has several limitations like that private or protected methods, constructors and attributes can not be used as pointcuts. However, I think in most cases this is not a big deal. If these things should be used anyway, consider using AspectJ’s compile time weaving.
In the following, I will quickly demonstrate how to integrate AOP with Spring and implement the a logging aspect. First of all, the aspectjweaver dependency has to be included in the pom.xml as this will provide some annotations used for defining an aspect. Its version is managed by Spring Boot.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| <dependency> | |
| <groupId>org.aspectj</groupId> | |
| <artifactId>aspectjweaver</artifactId> | |
| </dependency> |
There are two pointcuts defined in the logger aspect, the first for @RequestMapping and the second for @Profiled annotations. The aspect is called for all methods annotated with one of these annotations. For the case there are multiple aspects defined and triggered simultaneously, the aspect class is annotated with @Order and set to lowest precedence where with the execution order of the aspect is controlled.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| @Aspect | |
| @Order(Ordered.LOWEST_PRECEDENCE) | |
| @Component | |
| public class LoggerAspect { | |
| private Logger logger; | |
| public LoggerAspect() { | |
| logger = LoggerFactory.getLogger(getClass()); | |
| } | |
| @Pointcut("@annotation(org.springframework.web.bind.annotation.RequestMapping)") | |
| public void requestMapping() { | |
| } | |
| @Pointcut("@annotation(com.xovis.standalone_multisensor.aspects.Profiled)") | |
| public void profiled() { | |
| } | |
| @Around("requestMapping() || profiled()") | |
| public Object profile(ProceedingJoinPoint pjp) throws Throwable { | |
| StopWatch sw = new StopWatch(); | |
| String className = pjp.getTarget().getClass().getSimpleName(); | |
| String methodName = pjp.getSignature().getName(); | |
| String name = className + "." + methodName; | |
| logger.debug("call " + name); | |
| try { | |
| sw.start(); | |
| return pjp.proceed(); | |
| } finally { | |
| sw.stop(); | |
| logger.debug("exit " + name + " [" + sw.getTotalTimeMillis() + "ms]"); | |
| } | |
| } | |
| } |
@Profiled is a custom annotation and is implemented as follows:
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| @Retention(RetentionPolicy.RUNTIME) | |
| public @interface Profiled { | |
| } |
The output of an intercepted method will look like this
c.x.s.aspects.LoggerAspect: call StatusController.getStatus
c.x.s.aspects.LoggerAspect: exit StatusController.getStatus [15ms]
René Winkler 