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 protected], 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 protected], 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 protected], 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 protected], 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 protected], 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 protected], 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.
