【问题标题】:Log aop in reactive application with Spring WebFlux makes duplicate queries使用 Spring WebFlux 在反应式应用程序中记录 aop 进行重复查询
【发布时间】:2021-02-26 12:41:27
【问题描述】:

我正在使用带有关系数据库的 Spring Webflux 开发一个反应式应用程序,存储库查询是通过服务中的线程池进行的。这是我的 findById 方法的代码。

@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());
}

当我集成一个 AOP 日志来跟踪应用层时出现问题:

@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;
    }
}

在此代码中,当结果是 Mono 或 Flux 时,会显示结果: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)]

如果我更改我的代码以获得单声道或通量的值(在示例中只有单声道),对存储库的调用是重复的,我想这是因为必须在日志代码中完成订阅:

@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"]>

还有其他方法可以恢复 Flux 的价值吗?我不能使用 Mono.bock,因为它会锁定线程。

【问题讨论】:

  • 那么你的问题解决了吗?你愿意写一个正确的答案吗?
  • @MartinTarjányi 我已经添加了我的最终解决方案
  • 答案不属于问题。为了每个人的利益,请将其分解为正确的答案。您甚至可以接受自己的答案以结束问题。这就是您正确处理 SO 上的自我回答的方式。 ??????

标签: spring spring-webflux spring-aop reactive


【解决方案1】:

我的最终解决方案:

当结果是 Flux 打印每个元素的日志行时,我添加了一个 uuid 以便能够识别每个请求的跟踪。代码:

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;
    }
}

单声道日志:

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"]>

通量日志:

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)

【讨论】:

    猜你喜欢
    • 2019-03-09
    • 1970-01-01
    • 1970-01-01
    • 2012-11-04
    • 2020-04-29
    • 2020-12-23
    • 2019-04-12
    • 2018-02-08
    • 2015-09-02
    相关资源
    最近更新 更多