I am developing a reactive application with Spring Webflux with a relational database, the repository queries are made through a pool of threads in the service. This is the code for my findById method.
@Override
public Mono<UserDTO> findById(Long id) {
return Mono.defer(() -> Mono.just(userRepository.findById(id))).flatMap(optional -> {
if (optional.isPresent()) {
return Mono.just(convertToDto(optional.get()));
}
return Mono.empty();
}).subscribeOn(Schedulers.boundedElastic());
}
The problem appears when I integrate an AOP log to trace the application layers:
@Around("within(@org.springframework.stereotype.Controller *) || within(@org.springframework.stereotype.Service *) || execution(public !void org.springframework.data.repository.Repository+.*(..))")
public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("Enter: {}.{}() with argument[s] = {}", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), Arrays.toString(joinPoint.getArgs()));
}
try {
Object result = joinPoint.proceed();
LOGGER.debug("Exit: {}.{}() with result = {}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint
.getSignature().getName(), result);
return result;
} catch (IllegalArgumentException e) {
LOGGER.error("Illegal argument: {} in {}.{}()", Arrays.toString(joinPoint.getArgs()), joinPoint.getSignature()
.getDeclaringTypeName(),
joinPoint.getSignature().getName(), e);
throw e;
}
}
In this code when the result is a Mono or a Flux the result is shown: MonoSubscribeOn:
2020-11-14 22:35:25.394 DEBUG 31132 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Exit: com.*.springboot.webflux.api.app.services.UserServiceImpl.findById() with result = MonoSubscribeOn
2020-11-14 22:35:25.396 DEBUG 31132 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Exit: com.*.springboot.webflux.api.app.web.controllers.UserController.get() with result = MonoDefaultIfEmpty
2020-11-14 22:35:25.399 DEBUG 31132 --- [oundedElastic-3] *.webflux.api.app.aop.LoggingAspect : Enter: org.springframework.data.repository.CrudRepository.findById() with argument[s] = [1]
Hibernate:
select
user0_.id as id1_0_0_,
user0_.birthdate as birthdat2_0_0_,
user0_.email as email3_0_0_,
user0_.name as name4_0_0_,
user0_.surname as surname5_0_0_
from
users user0_
where
user0_.id=?
2020-11-14 22:35:25.417 DEBUG 31132 --- [oundedElastic-3] *.webflux.api.app.aop.LoggingAspect : Exit: org.springframework.data.repository.CrudRepository.findById() with result = Optional[User(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2020-11-14 22:35:17.221)]
If I change my code to obtain the value of the mono or the flux (in the example only the mono), the calls to the repository are duplicated, I suppose that because of the subcribe that must be done in the log code:
@Around("within(@org.springframework.stereotype.Controller *) || within(@org.springframework.stereotype.Service *) || execution(public !void org.springframework.data.repository.Repository+.*(..))")
public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
if (LOGGER.isDebugEnabled()) {
LOGGER.debug("Enter: {}.{}() with argument[s] = {}", joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), Arrays.toString(joinPoint.getArgs()));
}
try {
Object result = joinPoint.proceed();
if (LOGGER.isDebugEnabled()) {
if (result instanceof Mono) {
((Mono<Object>)result).subscribe(monoResult -> {
LOGGER.debug("Exit Mono: {}.{}() with result = {}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint
.getSignature().getName(), monoResult);
});
} else {
LOGGER.debug("Exit: {}.{}() with result = {}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint
.getSignature().getName(), result);
}
}
return result;
} catch (IllegalArgumentException e) {
LOGGER.error("Illegal argument: {} in {}.{}()", Arrays.toString(joinPoint.getArgs()), joinPoint.getSignature()
.getDeclaringTypeName(),
joinPoint.getSignature().getName(), e);
throw e;
}
}
Log result:
2020-11-14 22:38:16.693 DEBUG 21424 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Enter: org.springframework.data.repository.CrudRepository.findById() with argument[s] = [1]
2020-11-14 22:38:16.694 DEBUG 21424 --- [oundedElastic-4] *.webflux.api.app.aop.LoggingAspect : Enter: org.springframework.data.repository.CrudRepository.findById() with argument[s] = [1]
2020-11-14 22:38:16.699 DEBUG 21424 --- [oundedElastic-8] *.webflux.api.app.aop.LoggingAspect : Enter: org.springframework.data.repository.CrudRepository.findById() with argument[s] = [1]
Hibernate:
select
user0_.id as id1_0_0_,
user0_.birthdate as birthdat2_0_0_,
user0_.email as email3_0_0_,
user0_.name as name4_0_0_,
user0_.surname as surname5_0_0_
from
users user0_
where
user0_.id=?
Hibernate:
select
user0_.id as id1_0_0_,
user0_.birthdate as birthdat2_0_0_,
user0_.email as email3_0_0_,
user0_.name as name4_0_0_,
user0_.surname as surname5_0_0_
from
users user0_
where
user0_.id=?
Hibernate:
select
user0_.id as id1_0_0_,
user0_.birthdate as birthdat2_0_0_,
user0_.email as email3_0_0_,
user0_.name as name4_0_0_,
user0_.surname as surname5_0_0_
from
users user0_
where
user0_.id=?
2020-11-14 22:38:16.713 DEBUG 21424 --- [oundedElastic-8] *.webflux.api.app.aop.LoggingAspect : Exit: org.springframework.data.repository.CrudRepository.findById() with result = Optional[User(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2020-11-14 22:37:20.379)]
2020-11-14 22:38:16.713 DEBUG 21424 --- [oundedElastic-4] *.webflux.api.app.aop.LoggingAspect : Exit: org.springframework.data.repository.CrudRepository.findById() with result = Optional[User(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2020-11-14 22:37:20.379)]
2020-11-14 22:38:16.713 DEBUG 21424 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Exit: org.springframework.data.repository.CrudRepository.findById() with result = Optional[User(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2020-11-14 22:37:20.379)]
2020-11-14 22:38:16.713 DEBUG 21424 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Exit Mono: com.*.springboot.webflux.api.app.services.UserServiceImpl.findById() with result = UserDTO(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2020-11-14 22:37:20.379)
2020-11-14 22:38:16.714 DEBUG 21424 --- [oundedElastic-4] *.webflux.api.app.aop.LoggingAspect : Exit Mono: com.*.springboot.webflux.api.app.web.controllers.UserController.get() with result = <200 OK OK,UserDTO(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2020-11-14 22:37:20.379),[Content-Type:"application/json"]>
Any other alternative to recover the value of the Flux? I can't use Mono.bock as it locks the thread.
My final solution:
When the result is a Flux print a log line per element, I have added a uuid to be able to identify the trace of each request. Code:
public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
String uuid = UUID.randomUUID().toString();
try {
if (LOGGER.isDebugEnabled()) {
LOGGER.debug(LOG_ENTER_PATTERN, uuid, joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), Arrays.toString(joinPoint.getArgs()));
}
Object result = joinPoint.proceed();
if (LOGGER.isDebugEnabled()) {
if (result instanceof Mono) {
var monoResult = (Mono<?>) result;
return monoResult.doOnSuccess(o -> {
var response = "";
if (Objects.nonNull(o)) {
response = o.toString();
}
LOGGER.debug(LOG_EXIT_PATTERN, uuid,
joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
response);
});
}if (result instanceof Flux) {
var fluxResult = (Flux<?>) result;
return fluxResult.map(fluxItem -> {
LOGGER.debug(LOG_EXIT_PATTERN, uuid, joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), fluxItem);
return fluxItem;
});
} else {
LOGGER.debug(LOG_EXIT_PATTERN, uuid, joinPoint.getSignature().getDeclaringTypeName(),
joinPoint.getSignature().getName(), result);
}
}
return result;
} catch (IllegalArgumentException e) {
LOGGER.error(LOG_ERROR_ARROUND_PATTERN, uuid, Arrays.toString(joinPoint.getArgs()),
joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(), e);
throw e;
}
}
Log for Mono:
2020-11-15 11:54:05.845 DEBUG 33264 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Request uuid: ac0fbaec-59dc-429c-8a20-3053f7533fc9 -> Enter: com.*.springboot.webflux.api.app.web.controllers.UserController.get() with argument[s] = [1]
2020-11-15 11:54:05.845 DEBUG 33264 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Request uuid: 38760d52-01e6-449e-b464-7ffe0f0b7e86 -> Enter: com.*.springboot.webflux.api.app.services.UserServiceImpl.findById() with argument[s] = [1]
2020-11-15 11:54:05.846 INFO 33264 --- [ctor-http-nio-3] *.w.api.app.aop.ProfilingAspect : StopWatch 'Profiling': running time = 1122400 ns
---------------------------------------------
ns % Task name
---------------------------------------------
001122400 100 % execution(UserServiceImpl.findById(..))
2020-11-15 11:54:05.849 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 3466a23a-5087-44ba-86bc-617b577643db -> Enter: org.springframework.data.repository.CrudRepository.findById() with argument[s] = [1]
Hibernate:
select
user0_.id as id1_0_0_,
user0_.birthdate as birthdat2_0_0_,
user0_.email as email3_0_0_,
user0_.name as name4_0_0_,
user0_.surname as surname5_0_0_
from
users user0_
where
user0_.id=?
2020-11-15 11:54:05.860 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 3466a23a-5087-44ba-86bc-617b577643db -> Exit: org.springframework.data.repository.CrudRepository.findById() with result = Optional[User(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2011-12-18 13:17:17.0)]
2020-11-15 11:54:05.860 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 38760d52-01e6-449e-b464-7ffe0f0b7e86 -> Exit: com.*.springboot.webflux.api.app.services.UserServiceImpl.findById() with result = UserDTO(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2011-12-18 13:17:17.0)
2020-11-15 11:54:05.861 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: ac0fbaec-59dc-429c-8a20-3053f7533fc9 -> Exit: com.*.springboot.webflux.api.app.web.controllers.UserController.get() with result = <200 OK OK,UserDTO(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2011-12-18 13:17:17.0),[Content-Type:"application/json"]>
Log for Flux:
2020-11-15 11:52:30.905 DEBUG 33264 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Request uuid: 0d2e2c18-c9b3-491e-93e7-8fbbb5238224 -> Enter: com.*.springboot.webflux.api.app.web.controllers.UserController.findAll() with argument[s] = []
2020-11-15 11:52:30.914 DEBUG 33264 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Request uuid: 46a86774-de89-438a-afae-776b02751701 -> Enter: com.*.springboot.webflux.api.app.services.UserServiceImpl.findAll() with argument[s] = []
2020-11-15 11:52:30.927 INFO 33264 --- [ctor-http-nio-3] *.w.api.app.aop.ProfilingAspect : StopWatch 'Profiling': running time = 12118900 ns
---------------------------------------------
ns % Task name
---------------------------------------------
012118900 100 % execution(UserServiceImpl.findAll())
2020-11-15 11:52:30.934 DEBUG 33264 --- [ctor-http-nio-3] *.webflux.api.app.aop.LoggingAspect : Request uuid: 0d2e2c18-c9b3-491e-93e7-8fbbb5238224 -> Exit: com.*.springboot.webflux.api.app.web.controllers.UserController.findAll() with result = <200 OK OK,FluxMap,[Content-Type:"application/json"]>
2020-11-15 11:52:30.989 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: d4240286-c0e4-4eae-94ad-496079e2d9a0 -> Enter: org.springframework.data.jpa.repository.JpaRepository.findAll() with argument[s] = []
Hibernate:
select
user0_.id as id1_0_,
user0_.birthdate as birthdat2_0_,
user0_.email as email3_0_,
user0_.name as name4_0_,
user0_.surname as surname5_0_
from
users user0_
2020-11-15 11:52:31.144 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: d4240286-c0e4-4eae-94ad-496079e2d9a0 -> Exit: org.springframework.data.jpa.repository.JpaRepository.findAll() with result = [User(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2011-12-18 13:17:17.0), User(id=2, name=Oscar, surname=Suarez, email=oscar@mail.com, birthdate=2011-12-18 13:17:17.0), User(id=3, name=Maria, surname=Salgado, email=salgado@mail.com, birthdate=2011-12-18 13:17:17.0), User(id=4, name=Manuel, surname=Lopez, email=manuel@mail.com, birthdate=2011-12-18 13:17:17.0)]
2020-11-15 11:52:31.174 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 46a86774-de89-438a-afae-776b02751701 -> Exit: com.*.springboot.webflux.api.app.services.UserServiceImpl.findAll() with result = UserDTO(id=1, name=John, surname=Doe, email=john@mail.com, birthdate=2011-12-18 13:17:17.0)
2020-11-15 11:52:31.174 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 46a86774-de89-438a-afae-776b02751701 -> Exit: com.*.springboot.webflux.api.app.services.UserServiceImpl.findAll() with result = UserDTO(id=2, name=Oscar, surname=Suarez, email=oscar@mail.com, birthdate=2011-12-18 13:17:17.0)
2020-11-15 11:52:31.174 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 46a86774-de89-438a-afae-776b02751701 -> Exit: com.*.springboot.webflux.api.app.services.UserServiceImpl.findAll() with result = UserDTO(id=3, name=Maria, surname=Salgado, email=salgado@mail.com, birthdate=2011-12-18 13:17:17.0)
2020-11-15 11:52:31.174 DEBUG 33264 --- [oundedElastic-1] *.webflux.api.app.aop.LoggingAspect : Request uuid: 46a86774-de89-438a-afae-776b02751701 -> Exit: com.*.springboot.webflux.api.app.services.UserServiceImpl.findAll() with result = UserDTO(id=4, name=Manuel, surname=Lopez, email=manuel@mail.com, birthdate=2011-12-18 13:17:17.0)