修改支付相关

internal/biz/payment/payment.go

@@ -435,7 +435,14 @@ func (uc *PaymentUsecase) OrderEvents(ctx context.Context, provider, tradeNo str
 	return uc.orders.ListPaymentEvents(ctx, provider, tradeNo, limit)
 }
 
-func (uc *PaymentUsecase) Create(ctx context.Context, req *PaymentRequest) (*PaymentResult, error) {
+func (uc *PaymentUsecase) Create(ctx context.Context, req *PaymentRequest) (result *PaymentResult, err error) {
+	started := time.Now()
+	provider, tradeNo := "", ""
+	if req != nil {
+		provider, tradeNo = req.Provider, req.TradeNo
+	}
+	uc.logger.Info(ctx, "payment.create.started", "provider", provider, "trade_no", tradeNo)
+	defer func() { uc.logPaymentOperation(ctx, "create", started, provider, tradeNo, result, err) }()
 	if req == nil || !validPaymentText(req.Provider, 64) || !validPaymentText(req.TradeNo, 128) || !validPaymentText(req.BusinessType, 64) || !validPaymentText(req.BusinessID, 128) {
 		return nil, errors.New("支付参数不完整")
 	}
@@ -450,6 +457,8 @@ func (uc *PaymentUsecase) Create(ctx context.Context, req *PaymentRequest) (*Pay
 		return nil, err
 	}
 	req = prepared
+	uc.logger.Info(ctx, "payment.order.prepared", "provider", provider, "trade_no", tradeNo,
+		"business_type", req.BusinessType, "amount", req.Amount, "currency", req.Currency)
 	if !validPaymentText(req.Currency, 16) || !validPaymentText(req.Subject, 256) || req.Amount <= 0 {
 		return nil, errors.New("支付订单金额、币种或标题无效")
 	}
@@ -542,7 +551,10 @@ func IsDemoPaymentOrder(order *PaymentOrder) bool {
 	return order != nil && order.BusinessType == DemoBusinessType && strings.HasPrefix(strings.TrimSpace(order.TradeNo), "DEMO-PAY-")
 }
 
-func (uc *PaymentUsecase) Query(ctx context.Context, provider, tradeNo string) (*PaymentResult, error) {
+func (uc *PaymentUsecase) Query(ctx context.Context, provider, tradeNo string) (result *PaymentResult, err error) {
+	started := time.Now()
+	uc.logger.Info(ctx, "payment.query.started", "provider", provider, "trade_no", tradeNo)
+	defer func() { uc.logPaymentOperation(ctx, "query", started, provider, tradeNo, result, err) }()
 	if !validPaymentText(provider, 64) || !validPaymentText(tradeNo, 128) {
 		return nil, errors.New("查询支付参数不完整")
 	}
@@ -568,7 +580,8 @@ func (uc *PaymentUsecase) Query(ctx context.Context, provider, tradeNo string) (
 		}
 		queryID = order.ProviderTradeNo
 	}
-	result, err := uc.repo.Query(ctx, provider, queryID)
+	uc.logger.Info(ctx, "payment.provider.query.started", "provider", provider, "trade_no", tradeNo)
+	result, err = uc.repo.Query(ctx, provider, queryID)
 	if err != nil {
 		uc.logger.Error(ctx, "payment.query.failed", "provider", provider, "trade_no", tradeNo, "query_id", queryID, "error", err)
 		return nil, err
@@ -580,10 +593,15 @@ func (uc *PaymentUsecase) Query(ctx context.Context, provider, tradeNo string) (
 	if result.TradeNo != tradeNo {
 		return nil, errors.New("支付平台查单商户订单号不匹配")
 	}
+	uc.logger.Info(ctx, "payment.provider.query.checked", "provider", provider, "trade_no", tradeNo,
+		"provider_status", result.Status, "provider_trade_no", result.ProviderTradeNo)
 	return uc.reconcilePaymentResult(ctx, result, nil)
 }
 
-func (uc *PaymentUsecase) Refund(ctx context.Context, provider, tradeNo string, amount int64) (*PaymentResult, error) {
+func (uc *PaymentUsecase) Refund(ctx context.Context, provider, tradeNo string, amount int64) (result *PaymentResult, err error) {
+	started := time.Now()
+	uc.logger.Info(ctx, "payment.refund.started", "provider", provider, "trade_no", tradeNo, "amount", amount)
+	defer func() { uc.logPaymentOperation(ctx, "refund", started, provider, tradeNo, result, err) }()
 	if !validPaymentText(provider, 64) || !validPaymentText(tradeNo, 128) || amount <= 0 {
 		return nil, errors.New("退款参数不完整")
 	}
@@ -603,8 +621,26 @@ func (uc *PaymentUsecase) Refund(ctx context.Context, provider, tradeNo string,
 // TestProvider exercises the configured provider without requiring a business
 // module or a real customer order. Provider adapters use their configured
 // sandbox/test endpoint when one is selected in integration settings.
-func (uc *PaymentUsecase) TestProvider(ctx context.Context, provider string) (*PaymentTestResult, error) {
+func (uc *PaymentUsecase) TestProvider(ctx context.Context, provider string) (result *PaymentTestResult, err error) {
+	started := time.Now()
 	provider = strings.TrimSpace(provider)
+	uc.logger.Info(ctx, "payment.test.started", "provider", provider)
+	defer func() {
+		if result != nil {
+			for _, stage := range result.Stages {
+				uc.logger.Info(ctx, "payment.test.stage", "provider", provider, "trade_no", stage.TradeNo,
+					"stage", stage.Name, "status", stage.Status, "duration_ms", stage.Duration)
+			}
+			uc.logger.Info(ctx, "payment.test.summary", "provider", provider, "trade_no", result.TradeNo,
+				"passed", result.Passed, "full_flow", result.FullFlow)
+		}
+		var paymentResult *PaymentResult
+		tradeNo := ""
+		if result != nil {
+			paymentResult, tradeNo = result.Result, result.TradeNo
+		}
+		uc.logPaymentOperation(ctx, "test", started, provider, tradeNo, paymentResult, err)
+	}()
 	if !supportedPaymentProvider(provider) {
 		return nil, errors.New("不支持的支付渠道")
 	}
@@ -618,7 +654,10 @@ func (uc *PaymentUsecase) TestProvider(ctx context.Context, provider string) (*P
 // Fulfill retries delivery for an already-paid order. It is intentionally
 // idempotent: the repository lease prevents concurrent attempts and a
 // succeeded order is returned as a duplicate without invoking the handler.
-func (uc *PaymentUsecase) Fulfill(ctx context.Context, provider, tradeNo string) (*PaymentResult, error) {
+func (uc *PaymentUsecase) Fulfill(ctx context.Context, provider, tradeNo string) (result *PaymentResult, err error) {
+	started := time.Now()
+	uc.logger.Info(ctx, "payment.fulfill.started", "provider", provider, "trade_no", tradeNo)
+	defer func() { uc.logPaymentOperation(ctx, "fulfill", started, provider, tradeNo, result, err) }()
 	if !validPaymentText(provider, 64) || !validPaymentText(tradeNo, 128) {
 		return nil, errors.New("发货参数不完整")
 	}
@@ -632,7 +671,7 @@ func (uc *PaymentUsecase) Fulfill(ctx context.Context, provider, tradeNo string)
 	if IsDemoPaymentOrder(order) {
 		return nil, errors.New("演示订单不执行真实发货")
 	}
-	result := paymentResultFromOrder(order)
+	result = paymentResultFromOrder(order)
 	if result == nil {
 		return nil, ErrPaymentOrderNotFound
 	}
@@ -645,7 +684,20 @@ func (uc *PaymentUsecase) Fulfill(ctx context.Context, provider, tradeNo string)
 // Callback verifies the notification in the adapter, then always performs a
 // provider-side query before it can dispatch fulfillment. Callback payloads
 // are never trusted for amount, currency, or final payment state.
-func (uc *PaymentUsecase) Callback(ctx context.Context, callback *PaymentCallback) (*PaymentResult, error) {
+func (uc *PaymentUsecase) Callback(ctx context.Context, callback *PaymentCallback) (result *PaymentResult, err error) {
+	started := time.Now()
+	provider := ""
+	if callback != nil {
+		provider = callback.Provider
+	}
+	uc.logger.Info(ctx, "payment.callback.received", "provider", provider)
+	defer func() {
+		tradeNo := ""
+		if result != nil {
+			tradeNo = result.TradeNo
+		}
+		uc.logPaymentOperation(ctx, "callback", started, provider, tradeNo, result, err)
+	}()
 	if callback == nil || strings.TrimSpace(callback.Provider) == "" || len(callback.Body) == 0 {
 		err := errors.New("支付回调参数不完整")
 		uc.logger.Error(ctx, "payment.callback.invalid", "error", err)
@@ -686,6 +738,8 @@ func (uc *PaymentUsecase) createWithOrder(ctx context.Context, req *PaymentReque
 	if err != nil {
 		return nil, err
 	}
+	uc.logger.Info(ctx, "payment.order.persisted", "provider", req.Provider, "trade_no", req.TradeNo,
+		"created", created, "order_status", order.PaymentStatus)
 	if order.RequestFingerprint != paymentOrderFingerprint(req, extra) {
 		return nil, ErrPaymentOrderConflict
 	}
@@ -736,7 +790,7 @@ func (uc *PaymentUsecase) createWithOrder(ctx context.Context, req *PaymentReque
 		return uc.reconcilePaymentResult(ctx, result, nil)
 	}
 
-	uc.logger.Info(ctx, "payment.order.create", "provider", req.Provider, "trade_no", req.TradeNo, "business_type", req.BusinessType, "business_id", req.BusinessID)
+	uc.logger.Info(ctx, "payment.provider.create.started", "provider", req.Provider, "trade_no", req.TradeNo)
 	result, err := uc.repo.Create(ctx, req)
 	if err != nil {
 		uc.logger.Error(ctx, "payment.order.provider_create_failed", "provider", req.Provider, "trade_no", req.TradeNo, "error", err)
@@ -746,6 +800,8 @@ func (uc *PaymentUsecase) createWithOrder(ctx context.Context, req *PaymentReque
 		uc.logger.Error(ctx, "payment.order.provider_create_invalid", "provider", req.Provider, "trade_no", req.TradeNo, "error", err)
 		return nil, err
 	}
+	uc.logger.Info(ctx, "payment.provider.create.checked", "provider", req.Provider, "trade_no", req.TradeNo,
+		"provider_status", result.Status, "provider_trade_no", result.ProviderTradeNo)
 	update := paymentProviderUpdate(result)
 	update.EventSource = req.Provider
 	order, err = uc.orders.RecordPaymentCreate(ctx, req.Provider, req.TradeNo, update)
@@ -769,23 +825,27 @@ func (uc *PaymentUsecase) callbackWithOrder(ctx context.Context, callback *Payme
 		err = errors.New("支付回调渠道或商户订单号校验失败")
 		return nil, callbackResultError(callbackResult, err)
 	}
+	uc.logger.Info(ctx, "payment.callback.verified", "provider", callback.Provider, "trade_no", callbackResult.TradeNo)
 	queryID := callbackResult.QueryID
 	if queryID == "" {
 		queryID = callbackResult.TradeNo
 	}
+	uc.logger.Info(ctx, "payment.callback.provider_query.started", "provider", callback.Provider, "trade_no", callbackResult.TradeNo)
 	queryResult, err := uc.repo.Query(ctx, callbackResult.Provider, queryID)
 	if err != nil {
-		uc.logger.Error(ctx, "payment.callback.query_failed", "provider", callbackResult.Provider, "trade_no", callbackResult.TradeNo, "event_id", callbackResult.EventID, "error", err)
+		uc.logger.Error(ctx, "payment.callback.query_failed", "provider", callbackResult.Provider, "trade_no", callbackResult.TradeNo, "error", err)
 		return nil, callbackResultError(callbackResult, err)
 	}
 	if err = validatePaymentQueryResult(callbackResult.Provider, queryID, queryResult); err != nil {
-		uc.logger.Error(ctx, "payment.callback.query_invalid", "provider", callbackResult.Provider, "trade_no", callbackResult.TradeNo, "event_id", callbackResult.EventID, "error", err)
+		uc.logger.Error(ctx, "payment.callback.query_invalid", "provider", callbackResult.Provider, "trade_no", callbackResult.TradeNo, "error", err)
 		return nil, callbackResultError(callbackResult, err)
 	}
 	if queryResult.TradeNo != callbackResult.TradeNo {
 		err = errors.New("支付回调商户订单号与主动查单结果不匹配")
 		return nil, callbackResultError(callbackResult, err)
 	}
+	uc.logger.Info(ctx, "payment.callback.provider_query.checked", "provider", callback.Provider,
+		"trade_no", callbackResult.TradeNo, "provider_status", queryResult.Status)
 	queryResult = clonePaymentResult(queryResult)
 	queryResult.EventID = callbackResult.EventID
 	queryResult.SuccessAck = callbackResult.SuccessAck
@@ -829,6 +889,8 @@ func (uc *PaymentUsecase) reconcilePaymentResult(ctx context.Context, result, ca
 		uc.logger.Error(ctx, "payment.order.result_record_failed", "provider", result.Provider, "trade_no", result.TradeNo, "error", err)
 		return fail(err)
 	}
+	uc.logger.Info(ctx, "payment.order.reconciled", "provider", result.Provider, "trade_no", result.TradeNo,
+		"source", update.EventSource, "provider_status", result.Status, "order_status", order.PaymentStatus)
 	result = attachOrderResult(result, order)
 	if !strings.EqualFold(result.Status, "success") {
 		return result, nil
@@ -853,8 +915,10 @@ func (uc *PaymentUsecase) fulfillOrder(ctx context.Context, order *PaymentOrder,
 	if duplicate {
 		result.Duplicate = true
 		result.Status = "fulfilled"
+		uc.logger.Info(ctx, "payment.fulfillment.duplicate", "provider", result.Provider, "trade_no", result.TradeNo)
 		return attachOrderResult(result, order), nil
 	}
+	uc.logger.Info(ctx, "payment.fulfillment.started", "provider", result.Provider, "trade_no", result.TradeNo, "business_type", order.BusinessType)
 	handler := uc.fulfillments.Handler(order.BusinessType)
 	if handler == nil {
 		err = fmt.Errorf("支付发货 handler 未注册: %s", order.BusinessType)
@@ -877,6 +941,8 @@ func (uc *PaymentUsecase) fulfillOrder(ctx context.Context, order *PaymentOrder,
 	if err != nil {
 		return nil, err
 	}
+	uc.logger.Info(ctx, "payment.fulfillment.completed", "provider", result.Provider, "trade_no", result.TradeNo,
+		"fulfillment_status", order.FulfillmentStatus)
 	result.Status = "fulfilled"
 	return attachOrderResult(result, order), nil
 }
@@ -898,6 +964,8 @@ func (uc *PaymentUsecase) refundWithOrder(ctx context.Context, current *PaymentO
 	if err != nil {
 		return nil, err
 	}
+	uc.logger.Info(ctx, "payment.refund.reserved", "provider", provider, "trade_no", tradeNo,
+		"refund_no", order.RefundNo, "amount", amount, "currency", order.Currency)
 	if provider == PaymentInternal || current.PaymentMode == PaymentModeInternal {
 		processor, ok := handler.(PaymentInternalRefundProcessor)
 		if !ok {
@@ -930,6 +998,7 @@ func (uc *PaymentUsecase) refundWithOrder(ctx context.Context, current *PaymentO
 		}
 		return attachOrderResult(&PaymentResult{Provider: provider, TradeNo: tradeNo, ProviderTradeNo: refund.RefundID, Amount: amount, Currency: current.Currency, Payload: refund.Payload, Status: "refunded"}, order), nil
 	}
+	uc.logger.Info(ctx, "payment.provider.refund.started", "provider", provider, "trade_no", tradeNo, "refund_no", order.RefundNo)
 	result, providerErr := uc.repo.Refund(ctx, &PaymentRefundRequest{
 		Provider:        order.Provider,
 		TradeNo:         order.TradeNo,
@@ -943,6 +1012,10 @@ func (uc *PaymentUsecase) refundWithOrder(ctx context.Context, current *PaymentO
 	if providerErr == nil {
 		providerErr = validatePaymentRefundResult(provider, tradeNo, result)
 	}
+	if providerErr == nil {
+		uc.logger.Info(ctx, "payment.provider.refund.checked", "provider", provider, "trade_no", tradeNo,
+			"refund_no", order.RefundNo, "provider_status", result.Status)
+	}
 	if providerErr != nil && !errors.Is(providerErr, ErrPaymentOperationRejected) {
 		// A timeout or malformed response cannot prove that the provider did not
 		// accept the refund. Keep the durable refund operation and its idempotency
@@ -967,7 +1040,9 @@ func (uc *PaymentUsecase) refundWithOrder(ctx context.Context, current *PaymentO
 
 // ConfirmRefund is called by a provider-specific refund notification or a
 // reconciliation worker after the platform reports the final refund state.
-func (uc *PaymentUsecase) ConfirmRefund(ctx context.Context, provider, tradeNo, refundNo string, amount int64, success bool, message string) (*PaymentResult, error) {
+func (uc *PaymentUsecase) ConfirmRefund(ctx context.Context, provider, tradeNo, refundNo string, amount int64, success bool, message string) (result *PaymentResult, err error) {
+	started := time.Now()
+	defer func() { uc.logPaymentOperation(ctx, "refund_confirmation", started, provider, tradeNo, result, err) }()
 	if uc.orders == nil {
 		return nil, errors.New("支付订单仓储未接入")
 	}
@@ -978,7 +1053,7 @@ func (uc *PaymentUsecase) ConfirmRefund(ctx context.Context, provider, tradeNo,
 	if err != nil {
 		return nil, err
 	}
-	result := &PaymentResult{Provider: provider, TradeNo: tradeNo, Status: "refund_failed"}
+	result = &PaymentResult{Provider: provider, TradeNo: tradeNo, Status: "refund_failed"}
 	if success {
 		result.Status = "refunded"
 	}