补齐相关日志日志

internal/service/order.go

@@ -47,11 +47,14 @@ func (s *OrderService) Create(ctx context.Context, userID int64, request *dto.Or
 	goods, err := s.goodsDao.GoodsGetByCode(ctx, request.GoodsCode)
 	if err != nil {
 		if isNotFound(err) {
+			slog.InfoContext(ctx, "create order: goods not found", "user_id", userID, "goods_code", request.GoodsCode)
 			return nil, errcode.GoodsNotFound
 		}
+		slog.ErrorContext(ctx, "create order: query goods failed", "goods_code", request.GoodsCode, "error", err)
 		return nil, errcode.DatabaseError
 	}
 	if goods.Status != GoodsStatusOnShelf {
+		slog.InfoContext(ctx, "create order: goods off shelf", "user_id", userID, "goods_code", request.GoodsCode)
 		return nil, errcode.GoodsOffShelf
 	}
 
@@ -59,11 +62,14 @@ func (s *OrderService) Create(ctx context.Context, userID int64, request *dto.Or
 	user, uerr := s.userDao.UserGetByID(ctx, userID)
 	if uerr != nil {
 		if isNotFound(uerr) {
+			slog.WarnContext(ctx, "create order: user not found", "user_id", userID)
 			return nil, errcode.UserNotFound
 		}
+		slog.ErrorContext(ctx, "create order: query user failed", "user_id", userID, "error", uerr)
 		return nil, errcode.DatabaseError
 	}
 	if user.WxOpenID == "" {
+		slog.WarnContext(ctx, "create order: user openid missing", "user_id", userID)
 		return nil, errcode.OrderCreateFailed.WithDetails("缺少微信 openid")
 	}
 
@@ -93,14 +99,20 @@ func (s *OrderService) Create(ctx context.Context, userID int64, request *dto.Or
 	// 先落库再微信下单：微信下单失败时本地订单保留为待支付并超时自动过期，
 	// 避免「先微信下单、落库失败」产生无本地记录的孤儿预支付单。
 	if cerr := s.orderDao.OrderCreate(ctx, order); cerr != nil {
+		slog.ErrorContext(ctx, "create order: save order failed",
+			"order_no", orderNo, "user_id", userID, "goods_code", request.GoodsCode, "error", cerr)
 		return nil, errcode.OrderCreateFailed
 	}
 
 	payParams, perr := wechat.JsapiPrepay(ctx, user.WxOpenID, orderNo, goods.GoodsName, payAmount)
 	if perr != nil {
+		slog.ErrorContext(ctx, "create order: jsapi prepay failed", "order_no", orderNo, "user_id", userID, "error", perr)
 		return nil, errcode.OrderCreateFailed
 	}
 
+	slog.InfoContext(ctx, "order created",
+		"order_no", orderNo, "user_id", userID, "goods_code", request.GoodsCode, "pay_amount", payAmount)
+
 	return &dto.OrderCreateResponse{
 		OrderNo:    orderNo,
 		PayAmount:  payAmount,
@@ -122,16 +134,25 @@ func (s *OrderService) PayNotify(ctx context.Context, request *http.Request) *er
 
 	data, err := wechat.VerifyAndDecryptPayNotify(ctx, request)
 	if err != nil {
+		slog.ErrorContext(ctx, "pay notify: verify or decrypt failed", "remote_addr", request.RemoteAddr, "error", err)
 		return errcode.RPCError
 	}
 	if data.TradeState != "SUCCESS" {
+		slog.InfoContext(ctx, "pay notify: ignored non-success trade state",
+			"out_trade_no", data.OutTradeNo, "trade_state", data.TradeState)
 		return nil // 非支付成功，忽略。
 	}
 
 	// 幂等锁。
 	lockKey := fmtLockKey(redismodel.KeyLockPayCallback, data.OutTradeNo)
 	lockVal := genUUID()
-	if ok, _ := redisdao.TryLock(ctx, lockKey, lockVal, 30*time.Second); !ok {
+	ok, lerr := redisdao.TryLock(ctx, lockKey, lockVal, 30*time.Second)
+	if lerr != nil {
+		slog.ErrorContext(ctx, "pay notify: acquire lock failed", "out_trade_no", data.OutTradeNo, "error", lerr)
+		return nil // 锁不可用（Redis 故障）：不重复处理，交由微信重试/持锁者。
+	}
+	if !ok {
+		slog.DebugContext(ctx, "pay notify: concurrent callback, skip", "out_trade_no", data.OutTradeNo)
 		return nil // 并发回调，交由持锁者处理。
 	}
 	defer func() { _ = redisdao.Unlock(ctx, lockKey, lockVal) }()
@@ -143,6 +164,7 @@ func (s *OrderService) PayNotify(ctx context.Context, request *http.Request) *er
 			slog.ErrorContext(ctx, "pay notify: order not found", "out_trade_no", data.OutTradeNo)
 			return nil
 		}
+		slog.ErrorContext(ctx, "pay notify: query order failed", "out_trade_no", data.OutTradeNo, "error", gerr)
 		return errcode.DatabaseError
 	}
 	if data.Amount.Total != order.PayAmount {
@@ -166,9 +188,12 @@ func (s *OrderService) PayNotify(ctx context.Context, request *http.Request) *er
 	// 条件流转：待支付 -> 已支付，防重复回调。
 	updated, uerr := s.orderDao.OrderUpdateStatusByOrderNo(ctx, data.OutTradeNo, OrderStatusPending, OrderStatusPaid)
 	if uerr != nil {
+		slog.ErrorContext(ctx, "pay notify: update order status failed", "out_trade_no", data.OutTradeNo, "error", uerr)
 		return errcode.DatabaseError
 	}
 	if updated {
+		slog.InfoContext(ctx, "pay notify: order paid",
+			"order_no", order.OrderNo, "user_id", order.UserID, "pay_amount", order.PayAmount, "transaction_id", data.TransactionID)
 		s.finalizePaidOrder(ctx, order, data)
 		return nil
 	}
@@ -177,8 +202,10 @@ func (s *OrderService) PayNotify(ctx context.Context, request *http.Request) *er
 	current, gerr := s.orderDao.OrderGetByOrderNo(ctx, data.OutTradeNo)
 	if gerr != nil {
 		if isNotFound(gerr) {
+			slog.WarnContext(ctx, "pay notify: order disappeared after status conflict", "out_trade_no", data.OutTradeNo)
 			return nil
 		}
+		slog.ErrorContext(ctx, "pay notify: reload order failed", "out_trade_no", data.OutTradeNo, "error", gerr)
 		return errcode.DatabaseError
 	}
 
@@ -186,22 +213,28 @@ func (s *OrderService) PayNotify(ctx context.Context, request *http.Request) *er
 	case OrderStatusPaid:
 		// 已被并发回调处理。兜底确保支付信息与权益发放已完成（均幂等），
 		// 覆盖「订单已流转为 Paid 但权益发放前崩溃导致权益丢失」的场景。
-		_ = s.orderDao.OrderUpdateByOrderNo(ctx, current.OrderNo, map[string]any{
+		if uerr := s.orderDao.OrderUpdateByOrderNo(ctx, current.OrderNo, map[string]any{
 			"pay_time":       nowUnix(),
 			"transaction_id": data.TransactionID,
 			"callback_raw":   data.Raw,
-		})
+		}); uerr != nil {
+			slog.ErrorContext(ctx, "pay notify: reconcile paid order pay info failed", "order_no", current.OrderNo, "error", uerr)
+		}
+		slog.InfoContext(ctx, "pay notify: order already paid, reconcile benefits", "order_no", current.OrderNo, "user_id", current.UserID)
 		s.grantOrderBenefits(ctx, current)
 		return nil
 	case OrderStatusExpired:
 		// 订单被系统过期但用户已付款：过期 -> 已支付并补发货，避免用户付款却不到账。
 		ok, uerr := s.orderDao.OrderUpdateStatusByOrderNo(ctx, data.OutTradeNo, OrderStatusExpired, OrderStatusPaid)
 		if uerr != nil {
+			slog.ErrorContext(ctx, "pay notify: compensate expired order failed", "out_trade_no", data.OutTradeNo, "error", uerr)
 			return errcode.DatabaseError
 		}
 		if !ok {
+			slog.DebugContext(ctx, "pay notify: expired order already handled by another callback", "out_trade_no", data.OutTradeNo)
 			return nil // 已被其它回调处理。
 		}
+		slog.InfoContext(ctx, "pay notify: expired order compensated", "order_no", current.OrderNo, "user_id", current.UserID)
 		s.finalizePaidOrder(ctx, current, data)
 		return nil
 	case OrderStatusCancelled:
@@ -209,6 +242,7 @@ func (s *OrderService) PayNotify(ctx context.Context, request *http.Request) *er
 		s.autoRefundCancelledOrder(ctx, current, data)
 		return nil
 	default:
+		slog.DebugContext(ctx, "pay notify: unhandled order status", "out_trade_no", data.OutTradeNo, "order_status", current.OrderStatus)
 		return nil
 	}
 }
@@ -353,12 +387,19 @@ func (s *OrderService) RefundNotify(ctx context.Context, request *http.Request)
 
 	data, err := wechat.VerifyAndDecryptRefundNotify(ctx, request)
 	if err != nil {
+		slog.ErrorContext(ctx, "refund notify: verify or decrypt failed", "remote_addr", request.RemoteAddr, "error", err)
 		return errcode.RPCError
 	}
 
 	lockKey := fmtLockKey(redismodel.KeyLockRefundCallback, data.OutRefundNo)
 	lockVal := genUUID()
-	if ok, _ := redisdao.TryLock(ctx, lockKey, lockVal, 30*time.Second); !ok {
+	ok, lerr := redisdao.TryLock(ctx, lockKey, lockVal, 30*time.Second)
+	if lerr != nil {
+		slog.ErrorContext(ctx, "refund notify: acquire lock failed", "out_refund_no", data.OutRefundNo, "error", lerr)
+		return nil // 锁不可用（Redis 故障）：不重复处理，交由微信重试/持锁者。
+	}
+	if !ok {
+		slog.DebugContext(ctx, "refund notify: concurrent callback, skip", "out_refund_no", data.OutRefundNo)
 		return nil
 	}
 	defer func() { _ = redisdao.Unlock(ctx, lockKey, lockVal) }()
@@ -366,11 +407,14 @@ func (s *OrderService) RefundNotify(ctx context.Context, request *http.Request)
 	flow, ferr := s.refundDao.RefundFlowLogGetByRefundNo(ctx, data.OutRefundNo)
 	if ferr != nil {
 		if isNotFound(ferr) {
+			slog.WarnContext(ctx, "refund notify: refund flow not found", "out_refund_no", data.OutRefundNo)
 			return nil
 		}
+		slog.ErrorContext(ctx, "refund notify: get refund flow failed", "out_refund_no", data.OutRefundNo, "error", ferr)
 		return errcode.DatabaseError
 	}
 	if flow.Status == RefundStatusFailed {
+		slog.DebugContext(ctx, "refund notify: refund flow already failed, skip", "out_refund_no", data.OutRefundNo)
 		return nil
 	}
 	if data.Amount.Refund != flow.RefundAmount {
@@ -381,21 +425,30 @@ func (s *OrderService) RefundNotify(ctx context.Context, request *http.Request)
 		if flow.Status != RefundStatusSuccess {
 			ok, uerr := s.refundDao.RefundFlowLogUpdateStatusByFrom(ctx, data.OutRefundNo, flow.Status, map[string]any{"status": RefundStatusSuccess, "success_time": nowUnix(), "callback_raw": data.Raw})
 			if uerr != nil {
+				slog.ErrorContext(ctx, "refund notify: update refund flow status failed", "out_refund_no", data.OutRefundNo, "error", uerr)
 				return errcode.DatabaseError
 			}
 			if !ok {
+				slog.WarnContext(ctx, "refund notify: refund flow status changed concurrently", "out_refund_no", data.OutRefundNo)
 				return errcode.DatabaseError
 			}
 		}
 		order, gerr := s.orderDao.OrderGetByOrderNo(ctx, data.OutTradeNo)
 		if gerr != nil {
+			slog.ErrorContext(ctx, "refund notify: get order failed", "out_trade_no", data.OutTradeNo, "error", gerr)
 			return errcode.DatabaseError
 		}
 		if err := s.settleRefundSuccess(ctx, order, flow.RefundAmount); err != nil {
+			slog.ErrorContext(ctx, "refund notify: settle refund success failed",
+				"out_refund_no", data.OutRefundNo, "order_no", order.OrderNo, "error", err)
 			return errcode.DatabaseError
 		}
+		slog.InfoContext(ctx, "refund notify: refund success settled",
+			"order_no", order.OrderNo, "out_refund_no", data.OutRefundNo, "refund_amount", flow.RefundAmount)
 	} else if flow.Status != RefundStatusSuccess {
 		if _, err := s.refundDao.RefundFlowLogUpdateStatusByFrom(ctx, data.OutRefundNo, flow.Status, map[string]any{"status": RefundStatusFailed, "fail_reason": "微信退款未成功:" + data.RefundStatus, "callback_raw": data.Raw}); err != nil {
+			slog.ErrorContext(ctx, "refund notify: mark refund failed status failed",
+				"out_refund_no", data.OutRefundNo, "refund_status", data.RefundStatus, "error", err)
 			return errcode.DatabaseError
 		}
 	}
@@ -407,15 +460,20 @@ func (s *OrderService) RefundNotify(ctx context.Context, request *http.Request)
 func (s *OrderService) autoRefundCancelledOrder(ctx context.Context, order *mysqlmodel.Order, data *wechat.PayNotifyData) {
 	// 幂等：已有退款流水则跳过，避免重复生成待审核退款单。
 	if existing, err := s.refundDao.RefundFlowLogGetByOrderNo(ctx, order.OrderNo); err == nil && existing != nil {
+		slog.InfoContext(ctx, "auto refund: refund flow already exists, skip", "order_no", order.OrderNo)
 		return
+	} else if err != nil && !isNotFound(err) {
+		slog.ErrorContext(ctx, "auto refund: query existing refund flow failed", "order_no", order.OrderNo, "error", err)
 	}
 
 	// 补记支付信息（订单已取消，此前未记录），便于管理员审核退款时核对。
-	_ = s.orderDao.OrderUpdateByOrderNo(ctx, order.OrderNo, map[string]any{
+	if uerr := s.orderDao.OrderUpdateByOrderNo(ctx, order.OrderNo, map[string]any{
 		"pay_time":       nowUnix(),
 		"transaction_id": data.TransactionID,
 		"callback_raw":   data.Raw,
-	})
+	}); uerr != nil {
+		slog.ErrorContext(ctx, "auto refund: record pay info failed", "order_no", order.OrderNo, "error", uerr)
+	}
 
 	refundNo := genRefundNo()
 	flow := &mysqlmodel.RefundFlowLog{
@@ -435,8 +493,8 @@ func (s *OrderService) autoRefundCancelledOrder(ctx context.Context, order *mysq
 		slog.ErrorContext(ctx, "auto refund: create refund flow failed", "order_no", order.OrderNo, "error", err)
 		return
 	}
-	slog.InfoContext(ctx, "cancelled order refund flow created, waiting manual review",
-		"order_no", order.OrderNo, "refund_no", refundNo)
+	slog.WarnContext(ctx, "cancelled order refund flow created, waiting manual review",
+		"order_no", order.OrderNo, "user_id", order.UserID, "refund_no", refundNo, "refund_amount", order.PayAmount)
 }
 
 // ---- 内部辅助 ----
@@ -458,11 +516,13 @@ func (s *OrderService) getOwnedOrder(ctx context.Context, orderNo string, userID
 
 // finalizePaidOrder 记录支付信息、发放权益并发送通知（支付成功或过期补发货后调用）。
 func (s *OrderService) finalizePaidOrder(ctx context.Context, order *mysqlmodel.Order, data *wechat.PayNotifyData) {
-	_ = s.orderDao.OrderUpdateByOrderNo(ctx, order.OrderNo, map[string]any{
+	if uerr := s.orderDao.OrderUpdateByOrderNo(ctx, order.OrderNo, map[string]any{
 		"pay_time":       nowUnix(),
 		"transaction_id": data.TransactionID,
 		"callback_raw":   data.Raw,
-	})
+	}); uerr != nil {
+		slog.ErrorContext(ctx, "finalize paid order: update pay info failed", "order_no", order.OrderNo, "error", uerr)
+	}
 
 	s.grantOrderBenefits(ctx, order)
 
@@ -522,7 +582,7 @@ func (s *OrderService) grantBenefitIdempotent(ctx context.Context, order *mysqlm
 			// 曾失败过：冷却期内不重置（防微信回调重试风暴无限重置任务绕过重试上限），
 			// 冷却期外重置为待发放并尝试发放（发放本身有幂等兜底，重置失败仅告警）。
 			if nowUnix()-existing.UpdatedAt < benefitRetryCooldownSeconds {
-				slog.WarnContext(ctx, "benefit grant task in cooldown, skip retry",
+				slog.InfoContext(ctx, "benefit grant task in cooldown, skip retry",
 					"order_no", order.OrderNo, "benefit_type", benefitType, "task_id", existing.ID)
 				return
 			}
@@ -543,28 +603,43 @@ func (s *OrderService) grantBenefitIdempotent(ctx context.Context, order *mysqlm
 // executeGrant 认领并发放单个权益任务（claim 保证同一任务仅发放一次，防并发重复发放）。
 func (s *OrderService) executeGrant(ctx context.Context, task *mysqlmodel.BenefitGrantTask) {
 	var grantErr error
+	var granted bool
 	err := global.MysqlEngine.WithContext(ctx).Transaction(func(tx *gorm.DB) error {
 		var order mysqlmodel.Order
 		if err := tx.Select("id", "order_status").Clauses(clause.Locking{Strength: "UPDATE"}).Where("order_no = ?", task.OrderNo).First(&order).Error; err != nil {
 			return err
 		}
 		if order.OrderStatus != OrderStatusPaid {
+			slog.InfoContext(ctx, "grant benefit skipped: order not paid",
+				"order_no", task.OrderNo, "benefit_type", task.BenefitType)
 			return tx.Model(&mysqlmodel.BenefitGrantTask{}).Where("id = ? AND status IN ?", task.ID, []int8{BenefitTaskPending, BenefitTaskFailed}).Update("status", BenefitTaskCancelled).Error
 		}
 		res := tx.Model(&mysqlmodel.BenefitGrantTask{}).Where("id = ? AND status IN ?", task.ID, []int8{BenefitTaskPending, BenefitTaskFailed}).Update("status", BenefitTaskProcessing)
 		if res.Error != nil || res.RowsAffected == 0 {
+			if res.Error == nil {
+				slog.InfoContext(ctx, "grant benefit skipped: task already claimed or status changed",
+					"order_no", task.OrderNo, "benefit_type", task.BenefitType, "task_id", task.ID)
+			}
 			return res.Error
 		}
 		if e := s.doGrantBenefit(ctx, task); e != nil {
 			grantErr = e
 			return tx.Model(&mysqlmodel.BenefitGrantTask{}).Where("id = ?", task.ID).Updates(map[string]any{"status": BenefitTaskPending, "retry_count": gorm.Expr("retry_count + 1"), "last_error": e.Error()}).Error
 		}
+		granted = true
 		return tx.Model(&mysqlmodel.BenefitGrantTask{}).Where("id = ?", task.ID).Updates(map[string]any{"status": BenefitTaskSuccess, "last_error": ""}).Error
 	})
 	if err != nil {
-		slog.ErrorContext(ctx, "grant benefit task update failed", "order_no", task.OrderNo, "benefit_type", task.BenefitType, "error", err)
+		slog.ErrorContext(ctx, "grant benefit task update failed",
+			"order_no", task.OrderNo, "benefit_type", task.BenefitType, "user_id", task.UserID,
+			"retry_count", task.RetryCount, "amount", task.Amount, "error", err)
 	} else if grantErr != nil {
-		slog.ErrorContext(ctx, "grant benefit failed", "order_no", task.OrderNo, "benefit_type", task.BenefitType, "error", grantErr)
+		slog.ErrorContext(ctx, "grant benefit failed",
+			"order_no", task.OrderNo, "benefit_type", task.BenefitType, "user_id", task.UserID,
+			"retry_count", task.RetryCount, "amount", task.Amount, "error", grantErr)
+	} else if granted {
+		slog.InfoContext(ctx, "benefit granted",
+			"order_no", task.OrderNo, "benefit_type", task.BenefitType, "user_id", task.UserID, "amount", task.Amount)
 	}
 }
 
@@ -697,7 +772,9 @@ func (s *OrderService) grantVIP(ctx context.Context, userID, memberDays int64, o
 		return err
 	}
 	// 用户信息已变更，失效缓存。
-	_ = redisdao.UserInfoDel(ctx, userID)
+	if derr := redisdao.UserInfoDel(ctx, userID); derr != nil {
+		slog.DebugContext(ctx, "grant vip: invalidate user cache failed", "user_id", userID, "order_no", orderNo, "error", derr)
+	}
 	return nil
 }
 
@@ -710,7 +787,10 @@ func (s *OrderService) settleRefundSuccess(ctx context.Context, order *mysqlmode
 		return err
 	}
 	if settled {
+		slog.InfoContext(ctx, "refund settled", "order_no", order.OrderNo, "user_id", order.UserID, "refund_amount", refundAmount)
 		sendNotification(ctx, order.UserID, 0, NotificationTypeOrder, "退款成功", "订单「"+order.GoodsName+"」已退款")
+	} else {
+		slog.InfoContext(ctx, "refund settle skipped: order already settled or not in paid status", "order_no", order.OrderNo)
 	}
 	// 立即尝试；失败时任务仍为待处理，由定时任务恢复。
 	s.executeRevokeTaskByOrder(ctx, order.OrderNo)
@@ -738,7 +818,7 @@ func (s *OrderService) revokeOrderBenefits(ctx context.Context, order *mysqlmode
 func (s *OrderService) buildQuotaRevokeFlows(ctx context.Context, order *mysqlmodel.Order) ([]*mysqlmodel.QuotaFlowLog, error) {
 	grants, err := mysqldao.NewQuotaGrantDao().QuotaGrantListByRefID(ctx, order.OrderNo)
 	if err != nil {
-		slog.WarnContext(ctx, "list quota grants for revoke failed", "order_no", order.OrderNo, "error", err)
+		slog.ErrorContext(ctx, "list quota grants for revoke failed", "order_no", order.OrderNo, "error", err)
 		return nil, err
 	}
 
@@ -755,6 +835,9 @@ func (s *OrderService) buildQuotaRevokeFlows(ctx context.Context, order *mysqlmo
 		if !computed[g.QuotaType] {
 			if eff, qerr := getEffectiveQuota(ctx, order.UserID, g.QuotaType); qerr == nil {
 				current[g.QuotaType] = eff.Remain
+			} else {
+				slog.WarnContext(ctx, "build quota revoke flows: calc effective quota failed",
+					"order_no", order.OrderNo, "user_id", order.UserID, "quota_type", g.QuotaType, "error", qerr)
 			}
 			computed[g.QuotaType] = true
 		}
@@ -786,7 +869,9 @@ func (s *OrderService) revokeVIP(ctx context.Context, userID, memberDays int64,
 	if err := s.userDao.VIPRevokeIdempotent(ctx, userID, nowUnix(), memberDays, flow); err != nil && !isDuplicateKey(err) {
 		return err
 	}
-	_ = redisdao.UserInfoDel(ctx, userID)
+	if derr := redisdao.UserInfoDel(ctx, userID); derr != nil {
+		slog.DebugContext(ctx, "revoke vip: invalidate user cache failed", "user_id", userID, "order_no", orderNo, "error", derr)
+	}
 	return nil
 }