From 42e032308038e60a8d275dc59fed9f4abb4c97b6 Mon Sep 17 00:00:00 2001 From: dzc <2388224167@qq.com> Date: Fri, 23 Oct 2026 16:07:22 +0800 Subject: [PATCH] =?UTF-8?q?feat=EF=BC=9A=E4=B8=8B=E5=8D=95=E6=93=8D?= =?UTF-8?q?=E4=BD=9C=E5=86=99=E5=85=A5=E6=97=A5=E5=BF=97?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- docs/create-order-payment-timing.md | 58 ++++ .../config/PaymentTimingConfiguration.java | 56 ++++ .../CreateOrderPaymentTimingFilter.java | 54 ++++ .../controller/hard/HardApiController.java | 31 +- .../impl/order/HardOrderServiceImpl.java | 100 ++++--- .../hard/support/PaymentTimingTrace.java | 191 +++++++++++++ .../src/main/resources/logback-spring.xml | 12 + .../CreateOrderPaymentTimingFilterTest.java | 104 +++++++ .../HardOrderPaymentTimingRegressionTest.java | 267 ++++++++++++++++++ .../hard/support/PaymentTimingTraceTest.java | 132 +++++++++ 10 files changed, 957 insertions(+), 48 deletions(-) create mode 100644 docs/create-order-payment-timing.md create mode 100644 pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/PaymentTimingConfiguration.java create mode 100644 pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilter.java create mode 100644 pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/support/PaymentTimingTrace.java create mode 100644 pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilterTest.java create mode 100644 pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderPaymentTimingRegressionTest.java create mode 100644 pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/support/PaymentTimingTraceTest.java diff --git a/docs/create-order-payment-timing.md b/docs/create-order-payment-timing.md new file mode 100644 index 000000000..09a16af8c --- /dev/null +++ b/docs/create-order-payment-timing.md @@ -0,0 +1,58 @@ +# 消费机创建订单分段耗时 + +外部接口 `/hard/hard-api/ad/create-order` 对应 hard 服务内部 +`POST /hard-api/ad/create-order`。本次诊断仅观察该请求，不改变请求协议、 +事务注解、分布式锁、支付顺序、重试和返回值。 + +## 日志策略与开销 + +- 通过 `System.nanoTime()` 和请求内存中的阶段表计时，不新增 SQL、Redis 或 Feign 请求。 +- 正常且小于 1 秒的请求不新增摘要；慢请求、失败及阶段内被业务处理的异常输出一条 warning。 +- 摘要在过滤器链返回或抛错后统一生成，不在扣款写事务中逐阶段输出日志。 +- 专用 Logback 异步队列容量为 256，`neverBlock=true`。队列满时丢弃诊断摘要，不等待落盘。 +- 使用已有 `debug.log` 文件；不写入 DTO、人员资料、金额、令牌、付款码、图片或异常消息。 + +计时与内存分配存在少量开销，不能承诺零开销。异步队列优先保障请求返回， +日志管道持续拥堵时可能缺少部分诊断记录。 + +## 取日志与匹配 + +部署包含 Java 代码和 `logback-spring.xml` 改动的 hard 服务后，在 `debug.log` +搜索 `|终端支付耗时|`。按 `androidOrderCode` 与消费机的 `|支付耗时|` 摘要、 +原有订单 SQL 对齐；同号重试可通过不同的 `trace` 区分请求。 + +`outcome:failed` 是请求未正常完成，不能单凭这一字段判断钱包是否已经扣款； +仍需按原有订单对账逻辑确认。旁路通知或证据登记异常被业务自行处理时， +请求可能保持 `outcome:success`，异常类型保存在 `stageErrorTypes` 中。 + +## 主要阶段 + +| 字段 | 范围 | +| --- | --- | +| `pre_controller` | 请求监听器开始至 Controller 进入，含期间租户检查、认证、解析及校验 | +| `controller` | Controller 参数整理、Service 调用和返回对象创建 | +| `redis.lock` / `redis.unlock` | 原有 Redis 加锁、持锁检查及解锁 | +| `idempotency.lookup` / `idempotency.validate` | 原订单查询及重复请求一致性校验 | +| `prepare` | 下单准备整体，含下面的远程及本地查询 | +| `prepare.merchant` / `prepare.hardware` | 商户远程查询、设备本地查询 | +| `prepare.user` / `prepare.wallet` / `prepare.cart` | 用户、钱包及商品计价准备 | +| `transaction` | 原有代理事务调用，包含事务开始、提交及同步 afterCommit | +| `db.cart` / `db.orderInsert` | 购物车和订单写入 | +| `wallet.debit` | 原有钱包扣款远程调用 | +| `db.orderPaid` / `db.cartPaid` | 已支付状态更新 | +| `afterCommit.evidence` | 原有同步人脸证据元数据登记 | +| `postCommit.notify` | 原有提交后打印/播报分支 | + +`stagesInclusiveMs` 单位为毫秒，父阶段包含子阶段，不能直接相加。 +其他支付方式仍按原逻辑执行，日志可出现核销、库存及第三方支付阶段。 + +## 时间边界 + +监听器在 Servlet 过滤器之前记录起点，专用过滤器在原有租户过滤器之后、 +安全过滤器之前绑定请求追踪，不调整已有过滤器顺序。 +若请求在更早的租户过滤器中直接拒绝，尚未进入计时过滤器，则不会产生本摘要。 + +`totalMs` 截止过滤器链返回，不是客户端端到端耗时；不覆盖网关和入站网络、 +容器调用请求监听器前的排队、最后的响应传输，以及客户端本地处理。 +因此“客户端 4500ms、服务摘要 200ms”只能证明还需排查摘要计时区间之外的等待， +不能直接认定为 Flutter 程序卡顿。 diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/PaymentTimingConfiguration.java b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/PaymentTimingConfiguration.java new file mode 100644 index 000000000..13c9ed5e4 --- /dev/null +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/PaymentTimingConfiguration.java @@ -0,0 +1,56 @@ +package com.bsd.pjcloud.hard.config; + +import com.bsd.pjcloud.hard.config.filter.CreateOrderPaymentTimingFilter; +import jakarta.servlet.DispatcherType; +import jakarta.servlet.ServletRequestEvent; +import jakarta.servlet.ServletRequestListener; +import jakarta.servlet.http.HttpServletRequest; +import org.springframework.boot.web.servlet.FilterRegistrationBean; +import org.springframework.boot.web.servlet.ServletListenerRegistrationBean; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; +import org.springframework.core.Ordered; + +import java.util.function.LongSupplier; + +@Configuration(proxyBeanMethods = false) +public class PaymentTimingConfiguration { + /** 请求监听器先于全部过滤器，避免调整现有 Integer.MIN_VALUE 的租户过滤器顺序。 */ + @Bean + public ServletListenerRegistrationBean paymentTimingRequestStartListener() { + return new ServletListenerRegistrationBean<>(new RequestStartListener(System::nanoTime)); + } + + /** 租户检查之后、安全认证之前建立线程内追踪，耗时仍从监听器记录的时间开始。 */ + @Bean + public FilterRegistrationBean paymentTimingFilter() { + FilterRegistrationBean registration = + new FilterRegistrationBean<>(new CreateOrderPaymentTimingFilter()); + registration.setName("createOrderPaymentTimingFilter"); + registration.addUrlPatterns(CreateOrderPaymentTimingFilter.PATH); + registration.setDispatcherTypes(DispatcherType.REQUEST); + registration.setAsyncSupported(true); + registration.setOrder(Ordered.HIGHEST_PRECEDENCE + 1); + return registration; + } + + public static final class RequestStartListener implements ServletRequestListener { + private final LongSupplier clock; + + public RequestStartListener(LongSupplier clock) { + this.clock = clock; + } + + @Override + public void requestInitialized(ServletRequestEvent event) { + try { + if (event.getServletRequest() instanceof HttpServletRequest request + && CreateOrderPaymentTimingFilter.matches(request)) { + request.setAttribute(CreateOrderPaymentTimingFilter.STARTED_AT_ATTRIBUTE, clock.getAsLong()); + } + } catch (Throwable ignored) { + // 诊断监听器不参与请求受理；没有时间戳时过滤器从自身入口开始计时。 + } + } + } +} diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilter.java b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilter.java new file mode 100644 index 000000000..d6c4a696a --- /dev/null +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilter.java @@ -0,0 +1,54 @@ +package com.bsd.pjcloud.hard.config.filter; + +import com.bsd.pjcloud.hard.support.PaymentTimingTrace; +import jakarta.servlet.FilterChain; +import jakarta.servlet.ServletException; +import jakarta.servlet.http.HttpServletRequest; +import jakarta.servlet.http.HttpServletResponse; +import org.springframework.web.filter.OncePerRequestFilter; + +import java.io.IOException; +import java.util.function.LongFunction; + +/** 只观察同步的终端下单请求，不读取请求体、不更改响应或安全配置。 */ +public class CreateOrderPaymentTimingFilter extends OncePerRequestFilter { + public static final String PATH = "/hard-api/ad/create-order"; + public static final String STARTED_AT_ATTRIBUTE = CreateOrderPaymentTimingFilter.class.getName() + ".startedAtNanos"; + private final LongFunction opener; + + public CreateOrderPaymentTimingFilter() { + this(PaymentTimingTrace::open); + } + + public CreateOrderPaymentTimingFilter(LongFunction opener) { + this.opener = opener; + } + + public static boolean matches(HttpServletRequest request) { + String contextPath = request.getContextPath(); + return "POST".equals(request.getMethod()) + && ((contextPath == null ? "" : contextPath) + PATH).equals(request.getRequestURI()); + } + + @Override + protected boolean shouldNotFilter(HttpServletRequest request) { + return !matches(request); + } + + @Override + protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain) + throws ServletException, IOException { + Object start = request.getAttribute(STARTED_AT_ATTRIBUTE); + long startedAtNanos = start instanceof Long ? (Long) start : System.nanoTime(); + try (PaymentTimingTrace.Scope scope = opener.apply(startedAtNanos)) { + try { + chain.doFilter(request, response); + } catch (IOException | ServletException | RuntimeException | Error error) { + PaymentTimingTrace.markFailure(error); + throw error; + } finally { + scope.finish(response.getStatus()); + } + } + } +} diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/controller/hard/HardApiController.java b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/controller/hard/HardApiController.java index ac4d36f2b..aa4a5f329 100644 --- a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/controller/hard/HardApiController.java +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/controller/hard/HardApiController.java @@ -28,6 +28,7 @@ import com.bsd.pjcloud.hard.api.vo.order.HardCreateHardQrCodeScanOrderVo; import com.bsd.pjcloud.hard.api.vo.order.HardOrderVo; import com.bsd.pjcloud.hard.api.vo.order.HardOrderByAndroidCodeVo; import com.bsd.pjcloud.hard.service.*; +import com.bsd.pjcloud.hard.support.PaymentTimingTrace; import io.swagger.v3.oas.annotations.Operation; import io.swagger.v3.oas.annotations.security.SecurityRequirement; import io.swagger.v3.oas.annotations.tags.Tag; @@ -160,18 +161,28 @@ public class HardApiController { @Operation(summary = "创建订单") // Service 按设备和 androidOrderCode 加自动续期锁并复用已支付订单，旧终端无需新增字段。 public R createOrder(@Valid @RequestBody HardCreateOrderDto dto) { - // 处理商品类型 - if (ObjectUtil.isNotEmpty(dto.getList())) { - for (HardCreateCarDto item : dto.getList()) { - if (ObjectUtil.isEmpty(item.getProductNature())) continue; - if (ObjectUtil.isNotEmpty(item.getProductWeight()) && item.getProductWeight().compareTo(BigDecimal.valueOf(0)) != 0) { - item.setProductNature(HardProductNatureEnum.WEIGHT); - } else if (ObjectUtil.isNotEmpty(item.getProductCount())) { - item.setProductNature(HardProductNatureEnum.DEFAULT); + PaymentTimingTrace.markControllerEntered(); + PaymentTimingTrace.bind(dto.getAndroidOrderCode(), dto.getHardwareId()); + try { + return PaymentTimingTrace.call("controller", () -> { + // 处理商品类型 + if (ObjectUtil.isNotEmpty(dto.getList())) { + for (HardCreateCarDto item : dto.getList()) { + if (ObjectUtil.isEmpty(item.getProductNature())) continue; + if (ObjectUtil.isNotEmpty(item.getProductWeight()) && item.getProductWeight().compareTo(BigDecimal.valueOf(0)) != 0) { + item.setProductNature(HardProductNatureEnum.WEIGHT); + } else if (ObjectUtil.isNotEmpty(item.getProductCount())) { + item.setProductNature(HardProductNatureEnum.DEFAULT); + } + } } - } + return R.ok(hardwareOrderService.createOrder(dto)); + }); + } catch (RuntimeException | Error failure) { + // 业务异常可能被统一异常处理器转换为 HTTP 200，仍保留失败请求的计时摘要。 + PaymentTimingTrace.markFailure(failure); + throw failure; } - return R.ok(hardwareOrderService.createOrder(dto)); } @PostMapping("/create-hard-qr-code-order") diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderServiceImpl.java b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderServiceImpl.java index 20a68919a..6f05f0d05 100644 --- a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderServiceImpl.java +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderServiceImpl.java @@ -73,6 +73,7 @@ import com.bsd.pjcloud.hard.mapper.HardThirdMiOrderMapper; import com.bsd.pjcloud.hard.mapper.order.HardOrderMapper; import com.bsd.pjcloud.hard.service.*; import com.bsd.pjcloud.hard.service.order.HardOrderCartSnapshot; +import com.bsd.pjcloud.hard.support.PaymentTimingTrace; import com.bsd.pjcloud.supermarket.api.feign.RemoteMallProductService; import com.bsd.pjcloud.supermarket.api.feign.RemoteShopSkuService; import com.bsd.pjcloud.supermarket.api.feign.RemoteSupermarketSpuService; @@ -282,24 +283,28 @@ public class HardOrderServiceImpl extends ServiceImpl findTerminalOrder(dto.getAndroidOrderCode(), dto.getHardwareId())); if (existing != null) { - validateReusableOrder(existing, dto); + PaymentTimingTrace.run("idempotency.validate", () -> validateReusableOrder(existing, dto)); return existing.getId(); } // 远程只读查询全部先完成，数据库写事务不等待商户、用户、钱包和商品查询。 - context = prepareCreateOrder(dto); - orderId = getSelf().createOrderInTransaction(dto, context); + context = PaymentTimingTrace.call("prepare", () -> prepareCreateOrder(dto)); + // 包住代理调用，包含原事务的开启、提交及同步 afterCommit；阶段可嵌套，不能直接相加。 + orderId = PaymentTimingTrace.call("transaction", () -> getSelf().createOrderInTransaction(dto, context)); } finally { - if (lock.isHeldByCurrentThread()) lock.unlock(); + PaymentTimingTrace.run("redis.unlock", () -> { + if (lock.isHeldByCurrentThread()) lock.unlock(); + }); } // 提交后再生成打印/播报任务；旁路失败不能把已经扣款的订单反向报告为失败。 try { - getSelf().createOrderAfterSendMqMsg(orderId, context.userDetail); + PaymentTimingTrace.run("postCommit.notify", () -> getSelf().createOrderAfterSendMqMsg(orderId, context.userDetail)); } catch (Exception exception) { log.warn("|{}|订单已提交，通知失败|orderId:{}|", TAG, orderId, exception); } @@ -310,7 +315,7 @@ public class HardOrderServiceImpl extends ServiceImpl validateCreateOrderDto(dto)); if (ObjectUtil.isEmpty(mch)) throw new RuntimeException("机器绑定的商户不存在"); // 是否需要钱包支付 boolean isWalletPay = isPay(dto.getOrderType(), dto.getOrderPayType()); @@ -327,7 +332,8 @@ public class HardOrderServiceImpl extends ServiceImpl requireCreateOrderData(userService.getInnerByUserId(dto.getUserId()), "用户不存在")); if (ObjectUtil.isEmpty(userDetail.getSysUser())) throw new RuntimeException("用户不存在"); sysUser = userDetail.getSysUser(); } @@ -337,19 +343,23 @@ public class HardOrderServiceImpl extends ServiceImpl walletResult = remoteWalletService.getWalletById(dto.getWalletId()); + R walletResult = PaymentTimingTrace.call("prepare.wallet", + () -> remoteWalletService.getWalletById(dto.getWalletId())); wallet = requireCreateOrderData(walletResult, "用户钱包不存在"); } else { if (ObjectUtil.isEmpty(mch.getDefaultWalletTypeId())) { if (dto.getSysType().equals(HardTypeEnum.CANTEEN)) { - R walletResult = remoteWalletService.getWallet(dto.getUserId(), WalletTypeEnum.EAT); + R walletResult = PaymentTimingTrace.call("prepare.wallet", + () -> remoteWalletService.getWallet(dto.getUserId(), WalletTypeEnum.EAT)); wallet = requireCreateOrderData(walletResult, "用户钱包不存在"); } else { - R walletResult = remoteWalletService.getWallet(dto.getUserId(), WalletTypeEnum.PAY); + R walletResult = PaymentTimingTrace.call("prepare.wallet", + () -> remoteWalletService.getWallet(dto.getUserId(), WalletTypeEnum.PAY)); wallet = requireCreateOrderData(walletResult, "用户钱包不存在"); } } else { - R walletResult = remoteWalletService.getWalletByWalletTypeId(dto.getUserId(), mch.getDefaultWalletTypeId()); + R walletResult = PaymentTimingTrace.call("prepare.wallet", + () -> remoteWalletService.getWalletByWalletTypeId(dto.getUserId(), mch.getDefaultWalletTypeId())); wallet = requireCreateOrderData(walletResult, "用户钱包不存在"); } } @@ -364,15 +374,20 @@ public class HardOrderServiceImpl extends ServiceImpl validateCodeIsCancel(dto.getOrderType(), dto.getOrderSourceTypeId())); if (isCancel) throw new RuntimeException("该二维码已被核销"); } - HardOrderCartSnapshot cart = hardCarService.prepareCardWithCompute(dto.getSysType(), dto.getOrderType(), dto.getList()); + HardOrderCartSnapshot cart = PaymentTimingTrace.call("prepare.cart", + () -> hardCarService.prepareCardWithCompute(dto.getSysType(), dto.getOrderType(), dto.getList())); if (cart == null) { // 非收银业态仍沿用旧计价/摘要规则，所有商品查询同样在写事务外完成。 - int total = hardCarService.computerCarTotalPrice(dto.getSysType(), dto.getOrderType(), dto.getList()); - String subject = hardCarService.computerCarSubject(dto.getSysType(), dto.getOrderType(), dto.getList()); - cart = new HardOrderCartSnapshot(total, subject, hardCarService.prepareCard(dto.getSysType(), dto.getOrderType(), dto.getList())); + int total = PaymentTimingTrace.call("prepare.cartTotal", + () -> hardCarService.computerCarTotalPrice(dto.getSysType(), dto.getOrderType(), dto.getList())); + String subject = PaymentTimingTrace.call("prepare.cartSubject", + () -> hardCarService.computerCarSubject(dto.getSysType(), dto.getOrderType(), dto.getList())); + cart = new HardOrderCartSnapshot(total, subject, PaymentTimingTrace.call("prepare.cartDetails", + () -> hardCarService.prepareCard(dto.getSysType(), dto.getOrderType(), dto.getList()))); } int extraPrice = isExtraPrice && dto.getExtraPrice() != null ? dto.getExtraPrice() : 0; int payPrice = Math.addExact(cart.totalPrice(), extraPrice); @@ -399,7 +414,8 @@ public class HardOrderServiceImpl extends ServiceImpl hardCarService.createCardFromSnapshot(dto.getUserId(), dto.getMerchantId(), dto.getSysType(), context.cart)); // 添加硬件订单 HardOrderEntity orderObj = HardOrderEntity.builder() .androidOrderCode(dto.getAndroidOrderCode()) @@ -430,20 +446,20 @@ public class HardOrderServiceImpl extends ServiceImpl baseMapper.insert(orderObj)); registerEvidenceAfterCommit(orderObj, dto); // 扣减库存 - getSelf().fastenerInventory(orderObj, YesNoEnum.YES); + PaymentTimingTrace.run("stock.reduce", () -> getSelf().fastenerInventory(orderObj, YesNoEnum.YES)); // 钱包支付或者核销 if (isVerify || isWalletPay) { // 钱包扣款 try { - reduceOrderBalance(orderObj, false); + PaymentTimingTrace.run("payment", () -> reduceOrderBalance(orderObj, false)); } catch (InsufficientWalletBalanceException rejected) { // 不透支扣款可能因另一台终端抢先消费而明确失败，此时库存服务已经提交。 // 仅在余额不足的确定结果下恢复库存；超时等未知资金结果不能据此做补偿。 try { - getSelf().fastenerInventory(orderObj, YesNoEnum.NO); + PaymentTimingTrace.run("stock.restore", () -> getSelf().fastenerInventory(orderObj, YesNoEnum.NO)); } catch (Exception compensationFailure) { rejected.addSuppressed(compensationFailure); log.error("|{}|余额不足后的库存恢复失败，需核对库存|orderId:{}|", TAG, orderObj.getId(), compensationFailure); @@ -451,40 +467,44 @@ public class HardOrderServiceImpl extends ServiceImpl getSelf().cancelCode(orderObj, userDetail)); } // 现金支付 if (isOffline) { // 更改为支付成功 - getSelf().orderSuccess(orderObj, Boolean.FALSE); + PaymentTimingTrace.run("payment.offlineSuccess", () -> getSelf().orderSuccess(orderObj, Boolean.FALSE)); } // 微信支付 if (isWeChatPay) { WechatMicropayDto wechatPayDto = WechatMicropayDto.builder().merId(orderObj.getMerchantId()).orderId(orderObj.getId()).price(payPrice).wechatQrCode(String.valueOf(dto.getOrderSourceTypeId())).build(); - WechatMicropayVo wechatPayVo = wechatPayService.micropay(wechatPayDto); + WechatMicropayVo wechatPayVo = PaymentTimingTrace.call("payment.wechat", + () -> wechatPayService.micropay(wechatPayDto)); if (ObjectUtil.isEmpty(wechatPayVo)) { throw new RuntimeException("微信支付失败"); } boolean wehcantPaySuccess = wechatPayVo.isAllSuccess(); if (!wehcantPaySuccess) { // 如果微信支付订单返回不明确(不是支付成功)直接撤销支付 - wechatPayService.reverse(WechantReverseDto.builder().orderId(orderObj.getId()).build()); + PaymentTimingTrace.run("payment.wechatReverse", + () -> wechatPayService.reverse(WechantReverseDto.builder().orderId(orderObj.getId()).build())); throw new RuntimeException(wechatPayVo.getErr_code_des()); } else { - getSelf().orderSuccess(orderObj, Boolean.TRUE); + PaymentTimingTrace.run("payment.wechatSuccess", () -> getSelf().orderSuccess(orderObj, Boolean.TRUE)); } } // 支付宝支付 if (isAliPay) { AliMicropayDto wechatPayDto = AliMicropayDto.builder().merId(orderObj.getMerchantId()).orderId(orderObj.getId()).price(payPrice).subject(subject).authCode(String.valueOf(dto.getOrderSourceTypeId())).build(); - AlipayTradePayResponse micropay = alipayService.micropay(wechatPayDto); + AlipayTradePayResponse micropay = PaymentTimingTrace.call("payment.alipay", + () -> alipayService.micropay(wechatPayDto)); if (ObjectUtil.isEmpty(micropay) || !micropay.isSuccess()) { // 如果支付宝支付订单返回不明确(不是支付成功)直接撤销支付 - alipayService.reverse(AliReverseDto.builder().orderId(orderObj.getId()).build()); + PaymentTimingTrace.run("payment.alipayReverse", + () -> alipayService.reverse(AliReverseDto.builder().orderId(orderObj.getId()).build())); throw new RuntimeException(micropay == null ? "支付宝支付失败" : micropay.getSubMsg()); } else { orderObj.setOrderNo(micropay.getTradeNo()); - getSelf().orderSuccess(orderObj, Boolean.TRUE); + PaymentTimingTrace.run("payment.alipaySuccess", () -> getSelf().orderSuccess(orderObj, Boolean.TRUE)); } } return orderObj.getId(); @@ -616,7 +636,8 @@ public class HardOrderServiceImpl extends ServiceImpl { try { - hardOrderEvidenceImageService.registerOrderEvidence(order, dto.getEvidenceMetadataList(), dto.getAppVersion()); + PaymentTimingTrace.run("afterCommit.evidence", + () -> hardOrderEvidenceImageService.registerOrderEvidence(order, dto.getEvidenceMetadataList(), dto.getAppVersion())); } catch (Exception exception) { // 终端本地队列仍会按 androidOrderCode 补交，服务端占位失败不得改变订单支付结果。 log.warn("|{}|订单证据占位登记失败|orderId:{}|error:{}|", TAG, order.getId(), exception.getMessage()); @@ -1630,7 +1651,8 @@ public class HardOrderServiceImpl extends ServiceImpl reduceRes; try { - reduceRes = walletTransactionService.reduceWalletBalance(reduceBuild); + reduceRes = PaymentTimingTrace.call("wallet.debit", + () -> walletTransactionService.reduceWalletBalance(reduceBuild)); } catch (FeignException rejected) { // 钱包的全局异常处理器把余额不足包装成 HTTP 500 + R；Feign 会直接抛异常， // 必须只识别这个明确业务结果，不能把一般 500 或网关超时当作扣款未发生。 @@ -1647,7 +1669,7 @@ public class HardOrderServiceImpl extends ServiceImpl getSelf().orderSuccess(order, isWalletPay)); } } @@ -1679,11 +1701,11 @@ public class HardOrderServiceImpl extends ServiceImpl baseMapper.updateById(update)); // 父购物车订单表订单状态 if (ObjectUtil.isNotEmpty(order.getParentCarId())) { HardParentCarEntity updateParentCar = HardParentCarEntity.builder().id(order.getParentCarId()).orderStatus(HardOrderStatusEnum.PAY.getType()).build(); - hardParentCarServiceImpl.updateById(updateParentCar); + PaymentTimingTrace.run("db.cartPaid", () -> hardParentCarServiceImpl.updateById(updateParentCar)); } } @@ -2240,9 +2262,11 @@ public class HardOrderServiceImpl extends ServiceImpl requireCreateOrderData(remoteMchService.getById(dto.getMerchantId()), "商户不存在")); // 此处只取 deptId，按主键直查即可；getByHardId 还会联查部门和商户两次远程调用 - HardManagerEntity hard = hardManagerService.getById(dto.getHardwareId()); + HardManagerEntity hard = PaymentTimingTrace.call("prepare.hardware", + () -> hardManagerService.getById(dto.getHardwareId())); if (ObjectUtil.isEmpty(hard)) { throw new RuntimeException("设备不存在"); } diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/support/PaymentTimingTrace.java b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/support/PaymentTimingTrace.java new file mode 100644 index 000000000..1867903a6 --- /dev/null +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/main/java/com/bsd/pjcloud/hard/support/PaymentTimingTrace.java @@ -0,0 +1,191 @@ +package com.bsd.pjcloud.hard.support; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import java.util.LinkedHashMap; +import java.util.LinkedHashSet; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Consumer; +import java.util.function.LongSupplier; +import java.util.function.Supplier; +import java.util.regex.Pattern; +import java.util.stream.Collectors; + +/** 终端下单的请求内计时；不修改支付结果，也不记录 DTO、金额、人员或异常消息。 */ +public final class PaymentTimingTrace { + private static final Logger LOG = LoggerFactory.getLogger(PaymentTimingTrace.class); + private static final ThreadLocal CURRENT = new ThreadLocal<>(); + private static final AtomicLong SEQUENCE = new AtomicLong(); + private static final Pattern SAFE_IDENTIFIER = Pattern.compile("[A-Za-z0-9_.-]+"); + private static final long SLOW_NANOS = 1_000_000_000L; + + private PaymentTimingTrace() { + } + + /** 时间由 ServletRequestListener 在过滤器之前采集，包含租户与安全过滤器的等待。 */ + public static Scope open(long startedAtNanos) { + return open(startedAtNanos, System::nanoTime, LOG::warn); + } + + /** 可注入单调时钟与日志接收器，测试无需休眠或启动真实服务。 */ + public static Scope open(long startedAtNanos, LongSupplier clock, Consumer log) { + Scope scope = new Scope(startedAtNanos, clock, log, CURRENT.get()); + CURRENT.set(scope); + return scope; + } + + public static Scope current() { + return CURRENT.get(); + } + + public static void bind(String androidOrderCode, Long hardId) { + Scope scope = CURRENT.get(); + if (scope == null) return; + scope.androidOrderCode = safeIdentifier(androidOrderCode, 128, null); + scope.hardId = hardId; + } + + /** Controller 参数解析及校验完成后调用，之前的时间统一计入 pre_controller。 */ + public static void markControllerEntered() { + Scope scope = CURRENT.get(); + if (scope == null || scope.controllerEntered) return; + scope.controllerEntered = true; + scope.record("pre_controller", scope.elapsedNanos(), null); + } + + /** 只有请求最终失败时标记；阶段内被业务自行处理的异常不改变最终成功状态。 */ + public static void markFailure(Throwable error) { + Scope scope = CURRENT.get(); + if (scope == null) return; + scope.failed = true; + if (error != null) scope.errorTypes.add(errorType(error)); + } + + public static T call(String stage, Supplier callback) { + Scope scope = CURRENT.get(); + if (scope == null || scope.finished) return callback.get(); + long started = scope.elapsedNanos(); + Throwable failure = null; + try { + return callback.get(); + } catch (RuntimeException | Error error) { + failure = error; + throw error; + } finally { + scope.record(stage, scope.elapsedNanos() - started, failure); + } + } + + public static void run(String stage, Runnable callback) { + call(stage, () -> { + callback.run(); + return null; + }); + } + + public static final class Scope implements AutoCloseable { + private final long startedAtNanos; + private final LongSupplier clock; + private final Consumer log; + private final Scope previous; + private final String id; + private final Map stages = new LinkedHashMap<>(); + private final Map stageErrors = new LinkedHashMap<>(); + private final Set errorTypes = new LinkedHashSet<>(); + private String androidOrderCode; + private Long hardId; + private long lastElapsedNanos; + private boolean controllerEntered; + private boolean failed; + private boolean finished; + private boolean closed; + + private Scope(long startedAtNanos, LongSupplier clock, Consumer log, Scope previous) { + this.startedAtNanos = startedAtNanos; + this.clock = clock; + this.log = log; + this.previous = previous; + this.id = Long.toUnsignedString(startedAtNanos, 36) + "_" + SEQUENCE.incrementAndGet(); + } + + public String id() { + return id; + } + + /** 正常快请求不落日志，慢请求、失败及含被处理异常的请求只输出一条汇总。 */ + public void finish(int httpStatus) { + if (finished) return; + finished = true; + try { + long total = elapsedNanos(); + boolean requestFailed = failed || httpStatus >= 400; + if (total < SLOW_NANOS && !requestFailed && stageErrors.isEmpty()) return; + String stageSummary = stages.entrySet().stream() + .map(entry -> entry.getKey() + "=" + toMillis(entry.getValue())) + .collect(Collectors.joining(",")); + String stageErrorSummary = stageErrors.entrySet().stream() + .map(entry -> entry.getKey() + "=" + entry.getValue()) + .collect(Collectors.joining(",")); + log.accept("|终端支付耗时|trace:" + id + + (androidOrderCode == null ? "" : "|androidOrderCode:" + androidOrderCode) + + (hardId == null ? "" : "|hardId:" + hardId) + + "|httpStatus:" + httpStatus + "|outcome:" + (requestFailed ? "failed" : "success") + + "|totalMs:" + toMillis(total) + "|controllerEntered:" + controllerEntered + + "|stagesInclusiveMs:" + stageSummary + + "|stageErrorTypes:" + (stageErrorSummary.isEmpty() ? "-" : stageErrorSummary) + + "|errorTypes:" + (errorTypes.isEmpty() ? "-" : String.join(",", errorTypes)) + "|"); + } catch (Throwable ignored) { + // 诊断输出失败不能覆盖原请求结果或阻止 ThreadLocal 清理。 + } + } + + @Override + public void close() { + if (closed) return; + closed = true; + if (previous == null) CURRENT.remove(); + else CURRENT.set(previous); + } + + private long elapsedNanos() { + try { + long elapsed = clock.getAsLong() - startedAtNanos; + lastElapsedNanos = Math.max(lastElapsedNanos, elapsed); + } catch (Throwable ignored) { + // 测量来源故障时保留最近值，业务继续执行。 + } + return lastElapsedNanos; + } + + private void record(String stage, long durationNanos, Throwable failure) { + try { + if (finished) return; + String name = safeIdentifier(stage, 64, "unknown_stage"); + stages.merge(name, Math.max(0, durationNanos), Long::sum); + if (failure != null) { + String type = errorType(failure); + stageErrors.put(name, type); + errorTypes.add(type); + } + } catch (Throwable ignored) { + // 计时不可改变回调返回值、异常对象或业务异常传播路径。 + } + } + } + + private static long toMillis(long nanos) { + return nanos / 1_000_000L; + } + + private static String errorType(Throwable error) { + return safeIdentifier(error.getClass().getSimpleName(), 128, "Throwable"); + } + + private static String safeIdentifier(String value, int maxLength, String fallback) { + return value != null && !value.isEmpty() && value.length() <= maxLength + && SAFE_IDENTIFIER.matcher(value).matches() ? value : fallback; + } +} diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/main/resources/logback-spring.xml b/pjcloud-hardware/pjcloud-hardware-biz/src/main/resources/logback-spring.xml index 964ca8735..8337e4f02 100644 --- a/pjcloud-hardware/pjcloud-hardware-biz/src/main/resources/logback-spring.xml +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/main/resources/logback-spring.xml @@ -54,6 +54,18 @@ + + + 256 + 0 + true + false + + + + + + diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilterTest.java b/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilterTest.java new file mode 100644 index 000000000..f5ec747cd --- /dev/null +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/config/filter/CreateOrderPaymentTimingFilterTest.java @@ -0,0 +1,104 @@ +package com.bsd.pjcloud.hard.config.filter; + +import com.bsd.pjcloud.hard.config.PaymentTimingConfiguration; +import com.bsd.pjcloud.hard.support.PaymentTimingTrace; +import jakarta.servlet.ServletException; +import jakarta.servlet.ServletRequestEvent; +import org.junit.jupiter.api.Test; +import org.springframework.core.Ordered; +import org.springframework.mock.web.MockHttpServletRequest; +import org.springframework.mock.web.MockHttpServletResponse; +import org.springframework.mock.web.MockServletContext; + +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.concurrent.atomic.AtomicLong; + +import static org.junit.jupiter.api.Assertions.*; +import static org.mockito.Mockito.*; + +class CreateOrderPaymentTimingFilterTest { + @Test + void listenerTimeIncludesEarlierTenantFilterWaitAndRequestBodyIsNeverRead() throws Exception { + AtomicLong clock = new AtomicLong(10_000_000L); + List logs = new ArrayList<>(); + MockHttpServletRequest request = spy(new MockHttpServletRequest("POST", "/api" + CreateOrderPaymentTimingFilter.PATH)); + request.setContextPath("/api"); + var listener = new PaymentTimingConfiguration.RequestStartListener(clock::get); + listener.requestInitialized(new ServletRequestEvent(new MockServletContext(), request)); + clock.set(1_210_000_000L); // 在计时过滤器之前，租户或其他过滤器已经消耗 1200ms。 + var filter = new CreateOrderPaymentTimingFilter(start -> PaymentTimingTrace.open(start, clock::get, logs::add)); + filter.doFilter(request, new MockHttpServletResponse(), (req, response) -> { + PaymentTimingTrace.markControllerEntered(); + PaymentTimingTrace.bind("android_order", 77L); + PaymentTimingTrace.run("controller", () -> clock.set(1_360_000_000L)); + }); + + assertEquals(1, logs.size()); + assertTrue(logs.get(0).contains("totalMs:1350")); + assertTrue(logs.get(0).contains("pre_controller=1200")); + assertTrue(logs.get(0).contains("controller=150")); + assertNull(PaymentTimingTrace.current()); + verify(request, never()).getInputStream(); + verify(request, never()).getReader(); + } + + @Test + void exactPostRouteOnlyAndContextPathIsSupported() throws Exception { + AtomicInteger opened = new AtomicInteger(); + var filter = new CreateOrderPaymentTimingFilter(start -> { + opened.incrementAndGet(); + return PaymentTimingTrace.open(start); + }); + for (String path : List.of("/other", CreateOrderPaymentTimingFilter.PATH + "/", "/hard" + CreateOrderPaymentTimingFilter.PATH)) { + var request = new MockHttpServletRequest("POST", path); + filter.doFilter(request, new MockHttpServletResponse(), (req, response) -> assertNull(PaymentTimingTrace.current())); + } + var get = new MockHttpServletRequest("GET", CreateOrderPaymentTimingFilter.PATH); + filter.doFilter(get, new MockHttpServletResponse(), (req, response) -> assertNull(PaymentTimingTrace.current())); + assertEquals(0, opened.get()); + assertTrue(CreateOrderPaymentTimingFilter.matches(new MockHttpServletRequest("POST", CreateOrderPaymentTimingFilter.PATH))); + } + + @Test + void originalServletExceptionPropagatesAndLoggingFailureCannotLeakThreadLocal() { + var request = new MockHttpServletRequest("POST", CreateOrderPaymentTimingFilter.PATH); + request.setAttribute(CreateOrderPaymentTimingFilter.STARTED_AT_ATTRIBUTE, 0L); + var filter = new CreateOrderPaymentTimingFilter(start -> PaymentTimingTrace.open(start, () -> 0, + ignored -> { throw new IllegalStateException("logger failure"); })); + ServletException failure = new ServletException("private-request-data"); + ServletException caught = assertThrows(ServletException.class, + () -> filter.doFilter(request, new MockHttpServletResponse(), (req, response) -> { throw failure; })); + assertSame(failure, caught); + assertNull(PaymentTimingTrace.current()); + } + + @Test + void resolverHandledBusinessFailureStillProducesOneFailedSummary() throws Exception { + List logs = new ArrayList<>(); + var request = new MockHttpServletRequest("POST", CreateOrderPaymentTimingFilter.PATH); + request.setAttribute(CreateOrderPaymentTimingFilter.STARTED_AT_ATTRIBUTE, 0L); + var filter = new CreateOrderPaymentTimingFilter(start -> PaymentTimingTrace.open(start, () -> 0, logs::add)); + filter.doFilter(request, new MockHttpServletResponse(), (req, response) -> { + RuntimeException failure = new RuntimeException("business-secret"); + PaymentTimingTrace.markFailure(failure); + // 模拟 MVC 异常处理器已接住错误，最终仍以 HTTP 200 返回业务错误。 + }); + assertEquals(1, logs.size()); + assertTrue(logs.get(0).contains("httpStatus:200|outcome:failed")); + assertFalse(logs.get(0).contains("business-secret")); + assertNull(PaymentTimingTrace.current()); + } + + @Test + void listenerIsSelectiveAndConfigurationPreservesExistingFilterOrder() { + var listener = new PaymentTimingConfiguration.RequestStartListener(() -> 42L); + var skipped = new MockHttpServletRequest("GET", CreateOrderPaymentTimingFilter.PATH); + listener.requestInitialized(new ServletRequestEvent(new MockServletContext(), skipped)); + assertNull(skipped.getAttribute(CreateOrderPaymentTimingFilter.STARTED_AT_ATTRIBUTE)); + var registration = new PaymentTimingConfiguration().paymentTimingFilter(); + assertEquals(Ordered.HIGHEST_PRECEDENCE + 1, registration.getOrder()); + assertEquals(List.of(CreateOrderPaymentTimingFilter.PATH), List.copyOf(registration.getUrlPatterns())); + } +} diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderPaymentTimingRegressionTest.java b/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderPaymentTimingRegressionTest.java new file mode 100644 index 000000000..eacff2cde --- /dev/null +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/service/impl/order/HardOrderPaymentTimingRegressionTest.java @@ -0,0 +1,267 @@ +package com.bsd.pjcloud.hard.service.impl.order; + +import cn.hutool.extra.spring.SpringUtil; +import com.baomidou.mybatisplus.core.conditions.Wrapper; +import com.bsd.pjcloud.admin.api.dto.UserInfo; +import com.bsd.pjcloud.admin.api.entity.SysUser; +import com.bsd.pjcloud.admin.api.feign.RemoteUserService; +import com.bsd.pjcloud.common.core.constant.enums.YesNoEnum; +import com.bsd.pjcloud.common.core.util.KeyStrResolver; +import com.bsd.pjcloud.common.core.util.R; +import com.bsd.pjcloud.hard.api.constant.HardTypeEnum; +import com.bsd.pjcloud.hard.api.constant.order.HardOrderTypeEnum; +import com.bsd.pjcloud.hard.api.constant.order.HardPayTypeEnum; +import com.bsd.pjcloud.hard.api.dto.hard.HardCreateOrderDto; +import com.bsd.pjcloud.hard.api.dto.order.HardCreateCarDto; +import com.bsd.pjcloud.hard.api.entity.manager.HardManagerEntity; +import com.bsd.pjcloud.hard.api.entity.order.HardCarEntity; +import com.bsd.pjcloud.hard.api.entity.order.HardOrderEntity; +import com.bsd.pjcloud.hard.mapper.order.HardOrderMapper; +import com.bsd.pjcloud.hard.service.HardCarService; +import com.bsd.pjcloud.hard.service.HardManagerService; +import com.bsd.pjcloud.hard.service.order.HardOrderCartSnapshot; +import com.bsd.pjcloud.hard.support.PaymentTimingTrace; +import com.bsd.pjcloud.wallet.api.entity.WalletManageEntity; +import com.bsd.pjcloud.wallet.api.entity.WalletTransactionEntity; +import com.bsd.pjcloud.wallet.api.feign.RemoteMchService; +import com.bsd.pjcloud.wallet.api.feign.RemoteWalletService; +import com.bsd.pjcloud.wallet.api.feign.RemoteWalletTransactionService; +import com.bsd.pjcloud.wallet.api.vo.MchManageVo; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.mockito.InOrder; +import org.redisson.api.RLock; +import org.redisson.api.RedissonClient; +import org.springframework.context.ApplicationContext; +import org.springframework.context.support.GenericApplicationContext; +import org.springframework.test.util.ReflectionTestUtils; + +import java.math.BigDecimal; +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.atomic.AtomicLong; +import java.util.function.Supplier; + +import static org.junit.jupiter.api.Assertions.*; +import static org.mockito.ArgumentMatchers.*; +import static org.mockito.Mockito.*; + +/** Active timing must observe existing payment calls without repeating or reordering them. */ +class HardOrderPaymentTimingRegressionTest { + private HardOrderServiceImpl service; + private HardOrderMapper orders; + private HardCarService carts; + private HardManagerService managers; + private RemoteMchService merchants; + private RemoteUserService users; + private RemoteWalletService wallets; + private RemoteWalletTransactionService payments; + private RLock lock; + private GenericApplicationContext context; + private ApplicationContext previousContext; + private final List logs = new ArrayList<>(); + + @BeforeEach + void setup() { + service = mock(HardOrderServiceImpl.class, CALLS_REAL_METHODS); + orders = mock(HardOrderMapper.class); + carts = mock(HardCarService.class); + managers = mock(HardManagerService.class); + merchants = mock(RemoteMchService.class); + users = mock(RemoteUserService.class); + wallets = mock(RemoteWalletService.class); + payments = mock(RemoteWalletTransactionService.class); + RedissonClient redis = mock(RedissonClient.class); + KeyStrResolver keys = mock(KeyStrResolver.class); + lock = mock(RLock.class); + when(keys.extract(anyString(), eq(":"))).thenAnswer(call -> call.getArgument(0)); + when(redis.getLock(anyString())).thenReturn(lock); + when(lock.tryLock()).thenReturn(true); + when(lock.isHeldByCurrentThread()).thenReturn(true); + ReflectionTestUtils.setField(service, "baseMapper", orders); + ReflectionTestUtils.setField(service, "hardCarService", carts); + ReflectionTestUtils.setField(service, "hardManagerService", managers); + ReflectionTestUtils.setField(service, "remoteMchService", merchants); + ReflectionTestUtils.setField(service, "userService", users); + ReflectionTestUtils.setField(service, "remoteWalletService", wallets); + ReflectionTestUtils.setField(service, "walletTransactionService", payments); + ReflectionTestUtils.setField(service, "redissonClient", redis); + ReflectionTestUtils.setField(service, "keyStrResolver", keys); + // Only resolve the existing getSelf() lookup; no Boot, transaction or remote connection starts. + previousContext = SpringUtil.getApplicationContext(); + context = new GenericApplicationContext(); + context.registerBean("paymentTimingTestOrderService", HardOrderServiceImpl.class, () -> service); + context.refresh(); + new SpringUtil().setApplicationContext(context); + doNothing().when(service).fastenerInventory(any(), any(YesNoEnum.class)); + doNothing().when(service).orderSuccess(any(), anyBoolean()); + doNothing().when(service).cancelCode(any(), any()); + doNothing().when(service).createOrderAfterSendMqMsg(anyLong(), any()); + } + + @AfterEach + void cleanup() { + new SpringUtil().setApplicationContext(previousContext); + context.close(); + assertNull(PaymentTimingTrace.current()); + } + + @Test + void busyLockKeepsRejectionWithoutLookupPaymentOrUnlock() { + when(lock.tryLock()).thenReturn(false); + + RuntimeException failure = assertThrows(RuntimeException.class, + () -> observed(() -> service.createOrder(request()))); + + assertEquals("正在创建订单中，请勿重复操作", failure.getMessage()); + verify(lock).tryLock(); + verifyNoMoreInteractions(lock); + verifyZeroInteractions(orders, carts, managers, merchants, users, wallets, payments); + verify(service, never()).createOrderInTransaction(any(), any()); + assertTrue(logs.get(0).contains("outcome:failed")); + } + + @Test + void paidOrderReuseKeepsOneLocalLookupAndNoRemoteOrPaymentCalls() { + HardOrderEntity paid = HardOrderEntity.builder().id(100L).parentCarId(10L) + .hardId(3L).merchantId(2L).sysType(HardTypeEnum.CANTEEN.getType()) + .hourType("1").orderType(HardOrderTypeEnum.BELOW.getType()) + .payType(HardPayTypeEnum.FACE.getType()).userId(4L) + .extraPrice(0).orderStatus("5").build(); + when(orders.selectOne(any(Wrapper.class))).thenReturn(paid); + when(carts.getByParentCarId(10L)).thenReturn(snapshot().items()); + + assertEquals(100L, observed(() -> service.createOrder(request()))); + + InOrder calls = inOrder(lock, orders, carts); + calls.verify(lock).tryLock(); + calls.verify(orders).selectOne(any(Wrapper.class)); + calls.verify(carts).getByParentCarId(10L); + calls.verify(lock).isHeldByCurrentThread(); + calls.verify(lock).unlock(); + calls.verifyNoMoreInteractions(); + verifyZeroInteractions(managers, merchants, users, wallets, payments); + verify(service, never()).createOrderInTransaction(any(), any()); + verify(service, never()).createOrderAfterSendMqMsg(anyLong(), any()); + } + + @Test + void lookupFailurePropagatesSameExceptionAndStillReleasesHeldLock() { + RuntimeException databaseFailure = new RuntimeException("database unavailable"); + when(orders.selectOne(any(Wrapper.class))).thenThrow(databaseFailure); + + assertSame(databaseFailure, assertThrows(RuntimeException.class, + () -> observed(() -> service.createOrder(request())))); + + InOrder calls = inOrder(lock, orders); + calls.verify(lock).tryLock(); + calls.verify(orders).selectOne(any(Wrapper.class)); + calls.verify(lock).isHeldByCurrentThread(); + calls.verify(lock).unlock(); + calls.verifyNoMoreInteractions(); + verifyZeroInteractions(carts, managers, merchants, users, wallets, payments); + verify(service, never()).createOrderInTransaction(any(), any()); + verify(service, never()).createOrderAfterSendMqMsg(anyLong(), any()); + assertFalse(logs.get(0).contains("database unavailable")); + } + + @Test + void successKeepsPreparationWriteDebitUnlockAndNotificationOrder() { + stubPreparedOrder(); + when(orders.insert(any(HardOrderEntity.class))).thenAnswer(call -> { + assertTrue(logs.isEmpty(), "timing must not write logs inside order persistence"); + call.getArgument(0).setId(100L); + return 1; + }); + when(payments.reduceWalletBalance(any())).thenAnswer(call -> { + assertTrue(logs.isEmpty(), "timing must not write logs inside wallet debit"); + return R.ok(new WalletTransactionEntity()); + }); + + assertEquals(100L, observed(() -> service.createOrder(request()))); + + InOrder calls = inOrder(lock, orders, merchants, managers, users, wallets, carts, payments, service); + calls.verify(lock).tryLock(); + calls.verify(orders).selectOne(any(Wrapper.class)); + calls.verify(merchants).getById(2L); + calls.verify(managers).getById(3L); + calls.verify(users).getInnerByUserId(4L); + calls.verify(wallets).getWallet(eq(4L), any()); + calls.verify(carts).prepareCardWithCompute(any(), any(), anyList()); + calls.verify(service).createOrderInTransaction(any(), any()); + calls.verify(carts).createCardFromSnapshot(any(), any(), any(), any()); + calls.verify(orders).insert(any(HardOrderEntity.class)); + calls.verify(service).fastenerInventory(any(), eq(YesNoEnum.YES)); + calls.verify(payments).reduceWalletBalance(argThat(dto -> + Boolean.FALSE.equals(dto.getForce()) && dto.getPrice() == 350)); + calls.verify(service).orderSuccess(any(), eq(true)); + calls.verify(service).cancelCode(any(), any()); + calls.verify(lock).isHeldByCurrentThread(); + calls.verify(lock).unlock(); + calls.verify(service).createOrderAfterSendMqMsg(eq(100L), any()); + // Ignore service entry/private internal calls, but prohibit extra database or remote calls. + verifyNoMoreInteractions(orders, merchants, managers, users, wallets, carts, payments, lock); + verify(service, times(1)).createOrderInTransaction(any(), any()); + verify(service, times(1)).orderSuccess(any(), anyBoolean()); + verify(service, times(1)).createOrderAfterSendMqMsg(anyLong(), any()); + assertTrue(logs.get(0).contains("outcome:success")); + } + + private void stubPreparedOrder() { + MchManageVo merchant = new MchManageVo(); + merchant.setId(2L); + when(merchants.getById(2L)).thenReturn(R.ok(merchant)); + when(managers.getById(3L)).thenReturn(new HardManagerEntity()); + SysUser user = new SysUser(); + user.setUserId(4L); + UserInfo info = new UserInfo(); + info.setSysUser(user); + when(users.getInnerByUserId(4L)).thenReturn(R.ok(info)); + WalletManageEntity wallet = new WalletManageEntity(); + wallet.setId(5L); + wallet.setUserId(4L); + wallet.setBalance(500); + when(wallets.getWallet(eq(4L), any())).thenReturn(R.ok(wallet)); + when(carts.prepareCardWithCompute(any(), any(), anyList())).thenReturn(snapshot()); + when(carts.createCardFromSnapshot(any(), any(), any(), any())).thenReturn(10L); + } + + private T observed(Supplier action) { + AtomicLong clock = new AtomicLong(); + try (PaymentTimingTrace.Scope scope = PaymentTimingTrace.open(0, clock::get, logs::add)) { + PaymentTimingTrace.bind("legacy-code", 3L); + PaymentTimingTrace.markControllerEntered(); + int status = 200; + try { + T result = action.get(); + assertTrue(logs.isEmpty(), "stages must buffer until the request is complete"); + return result; + } catch (RuntimeException | Error failure) { + status = 500; + PaymentTimingTrace.markFailure(failure); + throw failure; + } finally { + clock.set(2_000_000_000L); + scope.finish(status); + assertEquals(1, logs.size()); + } + } + } + + private HardCreateOrderDto request() { + HardCreateCarDto item = new HardCreateCarDto(); + item.setProductId(6L); + item.setProductCount(1); + item.setProductWeight(BigDecimal.ZERO); + return HardCreateOrderDto.builder().androidOrderCode("legacy-code").hardwareId(3L).merchantId(2L) + .sysType(HardTypeEnum.CANTEEN).hourType(1).userId(4L).orderType(HardOrderTypeEnum.BELOW) + .orderPayType(HardPayTypeEnum.FACE).list(List.of(item)).build(); + } + + private HardOrderCartSnapshot snapshot() { + HardCarEntity item = HardCarEntity.builder().productId(6L).productCount(1).productWeight(BigDecimal.ZERO) + .productPrice(350).totalPrice(350L).isDiscountsProduct(YesNoEnum.NO.getCode()).build(); + return new HardOrderCartSnapshot(350, "饭菜x1;", List.of(item)); + } +} diff --git a/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/support/PaymentTimingTraceTest.java b/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/support/PaymentTimingTraceTest.java new file mode 100644 index 000000000..7f3fdc890 --- /dev/null +++ b/pjcloud-hardware/pjcloud-hardware-biz/src/test/java/com/bsd/pjcloud/hard/support/PaymentTimingTraceTest.java @@ -0,0 +1,132 @@ +package com.bsd.pjcloud.hard.support; + +import org.junit.jupiter.api.Test; + +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; + +import static org.junit.jupiter.api.Assertions.*; + +class PaymentTimingTraceTest { + @Test + void fastSuccessfulRequestDoesNotLogAndAlwaysClearsThreadLocal() { + AtomicLong clock = new AtomicLong(); + List logs = new ArrayList<>(); + try (PaymentTimingTrace.Scope scope = PaymentTimingTrace.open(0, clock::get, logs::add)) { + assertSame(scope, PaymentTimingTrace.current()); + assertEquals(7, PaymentTimingTrace.call("local_sql", () -> { + clock.set(20_000_000L); + return 7; + })); + scope.finish(200); + scope.finish(500); + } + assertTrue(logs.isEmpty()); + assertNull(PaymentTimingTrace.current()); + assertEquals(9, PaymentTimingTrace.call("inactive", () -> 9)); + } + + @Test + void summaryIncludesPreControllerAndInclusiveNestedStagesOnce() { + AtomicLong clock = new AtomicLong(); + List logs = new ArrayList<>(); + try (PaymentTimingTrace.Scope scope = PaymentTimingTrace.open(0, clock::get, logs::add)) { + PaymentTimingTrace.bind("android_123_456", 123L); + clock.set(1_200_000_000L); + PaymentTimingTrace.markControllerEntered(); + PaymentTimingTrace.markControllerEntered(); + PaymentTimingTrace.run("controller", () -> { + clock.set(1_300_000_000L); + PaymentTimingTrace.run("wallet_remote", () -> clock.set(1_500_000_000L)); + clock.set(1_600_000_000L); + }); + scope.finish(200); + scope.finish(200); + } + assertEquals(1, logs.size()); + String summary = logs.get(0); + assertTrue(summary.contains("androidOrderCode:android_123_456|hardId:123")); + assertTrue(summary.contains("outcome:success|totalMs:1600|controllerEntered:true")); + assertTrue(summary.contains("pre_controller=1200")); + assertTrue(summary.contains("controller=400")); + assertTrue(summary.contains("wallet_remote=200")); + } + + @Test + void handledStageErrorDoesNotReclassifySuccessfulPaymentOrExposePayload() { + AtomicLong clock = new AtomicLong(); + List logs = new ArrayList<>(); + IllegalStateException failure = new IllegalStateException("secret-token-and-user-body"); + try (PaymentTimingTrace.Scope scope = PaymentTimingTrace.open(0, clock::get, logs::add)) { + IllegalStateException caught = assertThrows(IllegalStateException.class, + () -> PaymentTimingTrace.run("notify", () -> { throw failure; })); + assertSame(failure, caught); + scope.finish(200); + } + assertEquals(1, logs.size()); + assertTrue(logs.get(0).contains("outcome:success")); + assertTrue(logs.get(0).contains("stageErrorTypes:notify=IllegalStateException")); + assertFalse(logs.get(0).contains("secret")); + } + + @Test + void explicitBusinessFailureIsLoggedEvenWhenExceptionResolverReturnsHttp200() { + List logs = new ArrayList<>(); + try (PaymentTimingTrace.Scope scope = PaymentTimingTrace.open(0, () -> 0, logs::add)) { + PaymentTimingTrace.bind("unsafe|payload=secret", 123L); + PaymentTimingTrace.markFailure(new IllegalArgumentException("secret")); + scope.finish(200); + } + assertEquals(1, logs.size()); + assertTrue(logs.get(0).contains("httpStatus:200|outcome:failed")); + assertTrue(logs.get(0).contains("errorTypes:IllegalArgumentException")); + assertFalse(logs.get(0).contains("androidOrderCode")); + assertFalse(logs.get(0).contains("secret")); + } + + @Test + void sinkAndClockFailuresDoNotReplaceResultAndNestedScopeRestoresPreviousTrace() { + try (PaymentTimingTrace.Scope outer = PaymentTimingTrace.open(0, () -> 0, ignored -> {})) { + try (PaymentTimingTrace.Scope inner = PaymentTimingTrace.open(0, + () -> { throw new IllegalStateException("clock"); }, + ignored -> { throw new IllegalStateException("sink"); })) { + assertEquals(8, PaymentTimingTrace.call("paid", () -> 8)); + assertDoesNotThrow(() -> inner.finish(500)); + } + assertSame(outer, PaymentTimingTrace.current()); + } + assertNull(PaymentTimingTrace.current()); + } + + @Test + void concurrentRequestsKeepSeparateThreadLocals() throws Exception { + var executor = Executors.newFixedThreadPool(2); + CountDownLatch opened = new CountDownLatch(2); + try { + var first = executor.submit(() -> isolatedRequest("first_order", opened)); + var second = executor.submit(() -> isolatedRequest("second_order", opened)); + assertTrue(first.get(5, TimeUnit.SECONDS).contains("androidOrderCode:first_order")); + assertTrue(second.get(5, TimeUnit.SECONDS).contains("androidOrderCode:second_order")); + assertNull(PaymentTimingTrace.current()); + } finally { + executor.shutdownNow(); + } + } + + private String isolatedRequest(String order, CountDownLatch opened) throws InterruptedException { + List logs = new ArrayList<>(); + try (PaymentTimingTrace.Scope scope = PaymentTimingTrace.open(0, () -> 0, logs::add)) { + PaymentTimingTrace.bind(order, 123L); + opened.countDown(); + assertTrue(opened.await(5, TimeUnit.SECONDS)); + assertSame(scope, PaymentTimingTrace.current()); + scope.finish(500); + } + assertNull(PaymentTimingTrace.current()); + return logs.get(0); + } +}