From a16b8f8e891fe9a1587935bfcabeb0d66270563f Mon Sep 17 00:00:00 2001 From: Yvan <8574526@qq,com> Date: Thu, 24 Sep 2026 17:44:17 +0800 Subject: [PATCH] =?UTF-8?q?=E4=BF=AE=E6=94=B9=E6=94=AF=E4=BB=98=E7=9B=B8?= =?UTF-8?q?=E5=85=B3?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- internal/biz/payment/payment.go | 101 ++++++++++++++++--- internal/biz/payment/payment_log.go | 56 +++++++++++ internal/biz/payment/payment_log_test.go | 117 +++++++++++++++++++++++ internal/biz/payment/payment_test.go | 6 +- internal/logging/zap.go | 2 + internal/logging/zap_test.go | 3 + 6 files changed, 270 insertions(+), 15 deletions(-) create mode 100644 internal/biz/payment/payment_log_test.go diff --git a/internal/biz/payment/payment.go b/internal/biz/payment/payment.go index bfe53e7..f6fb8cb 100644 --- a/internal/biz/payment/payment.go +++ b/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" } diff --git a/internal/biz/payment/payment_log.go b/internal/biz/payment/payment_log.go index abb9238..2063fec 100644 --- a/internal/biz/payment/payment_log.go +++ b/internal/biz/payment/payment_log.go @@ -2,7 +2,10 @@ package payment import ( "context" + "errors" "log/slog" + "net" + "time" ) // PaymentLogger isolates payment audit logging from the payment workflow and @@ -28,5 +31,58 @@ func (l *slogPaymentLogger) Info(ctx context.Context, message string, args ...an } func (l *slogPaymentLogger) Error(ctx context.Context, message string, args ...any) { + for i := 0; i+1 < len(args); i += 2 { + if key, ok := args[i].(string); ok && (key == "error" || key == "err") { + args[i] = "error_code" + if err, ok := args[i+1].(error); ok { + args[i+1] = paymentErrorCode(err) + } else { + args[i+1] = "redacted" + } + } + } l.logger.ErrorContext(ctx, message, args...) } + +func paymentErrorCode(err error) string { + switch { + case errors.Is(err, ErrPaymentOrderNotFound): + return "order_not_found" + case errors.Is(err, ErrPaymentProviderNotFound): + return "provider_not_configured" + case errors.Is(err, ErrPaymentOrderConflict): + return "order_conflict" + case errors.Is(err, ErrPaymentProviderConflict): + return "provider_conflict" + case errors.Is(err, ErrPaymentOrderBusy): + return "order_busy" + case errors.Is(err, ErrPaymentOrderState): + return "invalid_order_state" + case errors.Is(err, ErrPaymentOperationRejected): + return "provider_rejected" + case errors.Is(err, context.Canceled): + return "cancelled" + case errors.Is(err, context.DeadlineExceeded): + return "timeout" + default: + var networkError net.Error + if errors.As(err, &networkError) && networkError.Timeout() { + return "timeout" + } + return "operation_failed" + } +} + +func (uc *PaymentUsecase) logPaymentOperation(ctx context.Context, operation string, started time.Time, provider, tradeNo string, result *PaymentResult, err error) { + attrs := []any{"provider", provider, "trade_no", tradeNo, "duration_ms", time.Since(started).Milliseconds()} + if result != nil { + attrs = append(attrs, "provider_trade_no", result.ProviderTradeNo, "provider_status", result.Status, + "order_status", result.OrderStatus, "fulfillment_status", result.FulfillmentStatus, + "refund_status", result.RefundStatus, "duplicate", result.Duplicate) + } + if err != nil { + uc.logger.Error(ctx, "payment."+operation+".failed", append(attrs, "error_code", paymentErrorCode(err))...) + return + } + uc.logger.Info(ctx, "payment."+operation+".completed", attrs...) +} diff --git a/internal/biz/payment/payment_log_test.go b/internal/biz/payment/payment_log_test.go new file mode 100644 index 0000000..05a4bd4 --- /dev/null +++ b/internal/biz/payment/payment_log_test.go @@ -0,0 +1,117 @@ +package payment + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "log/slog" + "strings" + "testing" +) + +func TestPaymentLifecycleLogsDoNotIncludeProviderErrorsOrPayloads(t *testing.T) { + var output bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&output, nil)) + repo := &paymentRepoStub{createErr: errors.New("provider response: secret-token"), callbackErr: errors.New("callback body: secret-token")} + orders := &paymentOrderRepoStub{} + sources := NewPaymentOrderSourceRegistry() + if err := sources.Register(&paymentSourceStub{intent: &PaymentIntent{ + Provider: PaymentAlipay, TradeNo: "order-1", BusinessType: "game_item", BusinessID: "item-1", + Subject: "test item", Amount: 100, Currency: "CNY", + }}); err != nil { + t.Fatal(err) + } + uc := NewPaymentUsecase(repo, orders, nil, sources, nil, logger) + _, _ = uc.Create(context.Background(), &PaymentRequest{ + Provider: PaymentAlipay, TradeNo: "order-1", BusinessType: "game_item", BusinessID: "item-1", + Extra: map[string]any{"api_key": "secret-token"}, + }) + _, _ = uc.Callback(context.Background(), &PaymentCallback{Provider: PaymentAlipay, Body: []byte("secret-token")}) + + text := output.String() + if strings.Contains(text, "secret-token") { + t.Fatal("provider error or request payload leaked to payment log") + } + for _, stage := range []string{ + "payment.create.started", "payment.order.prepared", "payment.order.persisted", + "payment.provider.create.started", "payment.create.failed", + "payment.callback.received", "payment.callback.verify_failed", "payment.callback.failed", + } { + if !strings.Contains(text, stage) { + t.Errorf("missing lifecycle stage %s", stage) + } + } + for _, line := range strings.Split(strings.TrimSpace(text), "\n") { + var entry map[string]any + if err := json.Unmarshal([]byte(line), &entry); err != nil { + t.Fatalf("invalid structured log %q: %v", line, err) + } + if entry["mod"] != "payment" { + t.Fatalf("payment log module = %v", entry["mod"]) + } + if entry["msg"] == "payment.create.failed" && entry["duration_ms"] == nil { + t.Fatal("create failure did not record duration") + } + } +} + +func TestPaymentLogErrorUsesStableReasonWithoutOriginalMessage(t *testing.T) { + var output bytes.Buffer + logger := NewPaymentLogger(slog.New(slog.NewJSONHandler(&output, nil))) + logger.Error(context.Background(), "payment.test.failed", "error", PaymentRejected(errors.New("secret-token"))) + if strings.Contains(output.String(), "secret-token") || !strings.Contains(output.String(), `"error_code":"provider_rejected"`) { + t.Fatalf("unsafe or missing error code in %s", output.String()) + } + if got := paymentErrorCode(context.DeadlineExceeded); got != "timeout" { + t.Fatalf("deadline error code = %q, want timeout", got) + } +} + +func TestPaymentLogCorrelatesQueryFulfillmentAndRefund(t *testing.T) { + var output bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&output, nil)) + pending := successPaymentResult() + pending.Status = "pending" + repo := &paymentRepoStub{query: pending, refund: &PaymentResult{ + Provider: PaymentAlipay, TradeNo: "order-1", Status: "pending", Amount: 40, Currency: "CNY", + }} + orders := &paymentOrderRepoStub{order: testBizPaymentOrder()} + registry := NewPaymentFulfillmentRegistry() + if err := registry.Register(&paymentFulfillmentStub{}); err != nil { + t.Fatal(err) + } + uc := NewPaymentUsecase(repo, orders, nil, nil, registry, logger) + if _, err := uc.Query(context.Background(), PaymentAlipay, "order-1"); err != nil { + t.Fatal(err) + } + orders.order.PaymentStatus = PaymentStatusPaid + if _, err := uc.Fulfill(context.Background(), PaymentAlipay, "order-1"); err != nil { + t.Fatal(err) + } + if _, err := uc.Refund(context.Background(), PaymentAlipay, "order-1", 40); err != nil { + t.Fatal(err) + } + if _, err := uc.ConfirmRefund(context.Background(), PaymentAlipay, "order-1", "refund-1", 40, true, "confirmed"); err != nil { + t.Fatal(err) + } + for _, stage := range []string{ + "payment.provider.query.checked", "payment.order.reconciled", "payment.query.completed", + "payment.fulfillment.started", "payment.fulfillment.completed", + "payment.refund.reserved", "payment.provider.refund.checked", + "payment.refund.completed", "payment.refund_confirmation.completed", + } { + if !strings.Contains(output.String(), stage) { + t.Errorf("missing lifecycle stage %s", stage) + } + } + for _, line := range strings.Split(strings.TrimSpace(output.String()), "\n") { + var entry map[string]any + if err := json.Unmarshal([]byte(line), &entry); err != nil { + t.Fatal(err) + } + if entry["trade_no"] != "order-1" { + t.Fatalf("uncorrelated payment log: %s", line) + } + } +} diff --git a/internal/biz/payment/payment_test.go b/internal/biz/payment/payment_test.go index 6a05784..32d91bd 100644 --- a/internal/biz/payment/payment_test.go +++ b/internal/biz/payment/payment_test.go @@ -12,12 +12,14 @@ import ( type paymentRepoStub struct { create *PaymentResult + createErr error createdReq *PaymentRequest refund *PaymentResult refundErr error refundedReq *PaymentRefundRequest callback *PaymentResult query *PaymentResult + queryErr error queryCalls int callbackErr error } @@ -25,7 +27,7 @@ type paymentRepoStub struct { func (r *paymentRepoStub) Create(_ context.Context, req *PaymentRequest) (*PaymentResult, error) { copyReq := *req r.createdReq = ©Req - return r.create, nil + return r.create, r.createErr } type paymentOrderRepoStub struct { @@ -111,7 +113,7 @@ func (s *paymentSourceStub) PreparePayment(context.Context, string, string, stri } func (r *paymentRepoStub) Query(context.Context, string, string) (*PaymentResult, error) { r.queryCalls++ - return r.query, nil + return r.query, r.queryErr } func (r *paymentRepoStub) Refund(_ context.Context, req *PaymentRefundRequest) (*PaymentResult, error) { if req != nil { diff --git a/internal/logging/zap.go b/internal/logging/zap.go index 49cb89f..8b40d66 100644 --- a/internal/logging/zap.go +++ b/internal/logging/zap.go @@ -433,6 +433,8 @@ func routedLogPaths(module string, level zapcore.Level) []string { paths = append(paths, filepath.Join("http", "access.log")) case "timedTask": paths = append(paths, filepath.Join("timedTask", "task.log")) + case "payment", "payment-callback": + paths = append(paths, filepath.Join("payment", "payment.log")) case "websocket": paths = append(paths, filepath.Join("websocket", "websocket.log")) case "error": diff --git a/internal/logging/zap_test.go b/internal/logging/zap_test.go index 923637d..134752e 100644 --- a/internal/logging/zap_test.go +++ b/internal/logging/zap_test.go @@ -42,6 +42,8 @@ func TestZapHandlerRoutesHTTPAndErrorLogs(t *testing.T) { logger := slog.New(handler) logger.Info("request", "mod", "http", "request_id", "req-1") logger.Info("handshake", "mod", "websocket") + logger.Info("payment started", "mod", "payment", "trade_no", "order-1") + logger.Info("callback received", "mod", "payment-callback", "payment_provider", "wechat-v3") logger.Error("failed", "mod", "users") cleanup() @@ -54,6 +56,7 @@ func TestZapHandlerRoutesHTTPAndErrorLogs(t *testing.T) { filepath.Join(root, date, "application.log"), filepath.Join(root, date, "http", "access.log"), filepath.Join(root, date, "websocket", "websocket.log"), + filepath.Join(root, date, "payment", "payment.log"), filepath.Join(root, date, "users", "application.log"), filepath.Join(root, date, "error", "error.log"), }