Spring Boot AOP
Crear un @Aspect para interceptar la ejecución de una función
Table of contents
En esta ocasion aplicaremos el paradigma de Programación Orientada a Aspectos o AOP por sus siglas en inglés Aspect Oriented Programming.
Este paradigma nos permite separar las funcionalidades del sistema, en donde las funcionalidades generales del sistema se pueden usar traansversalmente y asi dejar las funciones modulares en cada uno de los modulos del sistema.
Actualmente Spring Boot soporta este paradigma a traves de la dependencia
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
Puede obtener mayor información de AOP para Spring Boot puede consultar el siguiente enlace Aspect Oriented Programming with Spring
Vamos a realizar un pequeño ejemplo de como emplear AOP para capturar la ejecución de un metodo y capturar el punto de cruce @Around
y agregar un registro en el log con el tiempo que demoro la ejecución del metodo.
Entorno
- maven.
- java 11
- IntetelliJ CE
Creando un @Aspect
Para crear un aspect debemos colocar la annotación @Aspect en la declaración de la clase.
@Aspect
@Service
public class LoggingAspect {
Con esta anotación le estamos indicando a Spring que esta clase aplicará ejecuciones de aspectos.
Creando un @Around
Para indicarle a Spring que queremos capturar el punto de cruce antes de la ejecución del metodo debemos realizar las siguientes acciones.
Primero creamos el metodo que deseamos aplicar en nuestro aspecto.
public Object logging(ProceedingJoinPoint joinPoint){
LOGGER.info("Executing Around method: {}", joinPoint.getSignature().getName());
long startTime = System.currentTimeMillis();
Object retVal = joinPoint.proceed();
long endTime = System.currentTimeMillis();
long time = endTime - startTime;
LOGGER.info("Took {} seg.", (time/1000));
return retVal;
}
Ahora agregamos nuestra anotación
@Around
al metodo creado.
@Around
public Object logging(ProceedingJoinPoint joinPoint){
LOGGER.info("Executing Around method: {}", joinPoint.getSignature().getName());
long startTime = System.currentTimeMillis();
Object retVal = joinPoint.proceed();
long endTime = System.currentTimeMillis();
long time = endTime - startTime;
LOGGER.info("Took {} seg.", (time/1000));
return retVal;
}
Por ultimo timo indicamos el punto de cruce en el cual deseamos que se ejecute nuestro metodo. En este caso usaremos
execution(* com.hvs..*(..))
para indicar que se dispare para cualquier ejecución de un metodo dentro de nuestro paquete principalcom.hvs
con cualquier argumento.
@Around(execution("* com.hvs..*(..))")
public Object logging(ProceedingJoinPoint joinPoint){
LOGGER.info("Executing Around method: {}", joinPoint.getSignature().getName());
long startTime = System.currentTimeMillis();
Object retVal = joinPoint.proceed();
long endTime = System.currentTimeMillis();
long time = endTime - startTime;
LOGGER.info("Took {} seg.", (time/1000));
return retVal;
}
Ejecutando la aplicación
Para validar este aspecto hemos creado un controlador de spring boot el cual calcula un valor random dentro de una rnago de dos numeros que recibe como parametros.
@GetMapping(value = {"/${action-delay}/{min}/{max}"})
public long delay(@PathVariable long min, @PathVariable long max) {
LOGGER.info("into my method");
if (min == 0) {
min = defaultMin;
}
if (max == 0) {
max = defaultMax;
}
if (min < 0){
throw new IllegalArgumentException("min value should not be < 0");
}
if (max < min) {
throw new IllegalArgumentException("max value should not be bigger that min value");
}
long delay = min + (long) (Math.random() * (max - min));
sleep((delay * 1000));
return delay;
}
Luego, solo debemos ejecutar nuestra aplicación, hacer el consumo del controllador y comprobar que en nuestro log se visualice el tiempo que tomo la ejecución del metodo.
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.5.4)
2021-10-07 14:16:10.027 INFO 4060142 --- [ main] com.hvs.lab.aop.AOPApplication : Starting AOPApplication using Java 11.0.11 on cotetec099 with PID 4060142 (/home/hmartinez/IdeaProjects/lab-1-aop-spring/target/classes started by hmartinez in /home/hmartinez/IdeaProjects/lab-1-aop-spring)
2021-10-07 14:16:10.028 INFO 4060142 --- [ main] com.hvs.lab.aop.AOPApplication : No active profile set, falling back to default profiles: default
2021-10-07 14:16:11.499 INFO 4060142 --- [ main] o.s.b.web.embedded.netty.NettyWebServer : Netty started on port 8080
2021-10-07 14:16:11.505 INFO 4060142 --- [ main] com.hvs.lab.aop.AOPApplication : Started AOPApplication in 2.11 seconds (JVM running for 2.701)
2021-10-07 14:16:14.533 INFO 4060142 --- [or-http-epoll-3] com.hvs.lab.aop.aspect.LoggingAspect : Executing Around method: delay
2021-10-07 14:16:14.542 INFO 4060142 --- [or-http-epoll-3] c.h.l.a.c.i.DelayRandomController : into my method
2021-10-07 14:16:19.542 INFO 4060142 --- [or-http-epoll-3] com.hvs.lab.aop.aspect.LoggingAspect : Took 5 seg.
Al final de la ejecución podemos ver Took 5 seg.
indicandonos que tomo 5 segundo la ejecución del metodo con lo cual comprobamos que el aspecto se ejecuto correctamente.
Puede ver el código completo de este ejemplo aquí