修复(#136): EPay notify 静默失败硬化 + 回写 trade_no

P01 签名校验失败由 return nil 改为返回 xerr.SignatureInvalid，handler 回 400，EPay 网关重试；Debug 旁路保留 P02 订单不存在维持 error 返回，仅 status=5 Finished 保留 nil 作幂等短路 P03 支付完成路径写入 order.trade_no = req.TradeNo，再 UpdateOrderStatus 刷缓存附加：TradeStatus != TRADE_SUCCESS 降为 INFO 日志 + metric epay_notify_trade_not_success 抽离纯决策函数 evaluateEPayNotify，新增单测覆盖 4 个核心分支 + 签名优先级回归 + SQL 写路径 + URL 解析（9/9 PASS，-race 干净）仅 internal/logic/notify/ePayNotifyLogic.go 与对应单测，无其他文件变更。 Co-authored-by: multica-agent <github@multica.ai>
2026-06-01 03:08:31 -07:00
parent aa11588c8f
commit 750b7be424
2 changed files with 271 additions and 7 deletions
@@ -13,6 +13,7 @@ import (
 	"github.com/gin-gonic/gin"

 	"github.com/hibiken/asynq"
+	"github.com/perfect-panel/server/internal/model/order"
 	"github.com/perfect-panel/server/internal/model/payment"
 	"github.com/perfect-panel/server/internal/svc"
 	"github.com/perfect-panel/server/internal/types"
@@ -22,6 +23,47 @@ import (
 	queueType "github.com/perfect-panel/server/queue/types"
 )

+// epayNotifyTradeNotSuccess identifies the "buyer paid but trade not in TRADE_SUCCESS
+// terminal state" branch in metrics / log search. EPay is told 200 here so it will
+// not retry; we still want it visible for monitoring (HIF-135 / HIF-136).
+const epayNotifyTradeNotSuccess = "epay_notify_trade_not_success"
+
+// epayNotifyDecision encodes the post-parse decision so the branching logic can be
+// unit-tested without spinning up a real OrderModel / Redis / asynq stack.
+type epayNotifyDecision int
+
+const (
+	// epayNotifyDecisionRejectSign: signature is invalid and debug bypass is off.
+	// Caller MUST return an error so the handler responds non-200 and EPay retries.
+	epayNotifyDecisionRejectSign epayNotifyDecision = iota
+	// epayNotifyDecisionAckTradeNotSuccess: trade_status != TRADE_SUCCESS
+	// (user cancelled / failed at gateway). Acknowledge with 200 "success" and emit
+	// a metric-named log for monitoring.
+	epayNotifyDecisionAckTradeNotSuccess
+	// epayNotifyDecisionAckIdempotent: order already at Finished (status=5).
+	// Repeat callback — ack with 200 "success", do not re-enqueue activation.
+	epayNotifyDecisionAckIdempotent
+	// epayNotifyDecisionProcess: happy path. Write trade_no, flip status to Paid,
+	// enqueue activation task.
+	epayNotifyDecisionProcess
+)
+
+// evaluateEPayNotify is a pure decision function so each branch can be unit-tested
+// without DB/Redis. Caller has already located the order; orderStatus is the
+// current status from the DB row.
+func evaluateEPayNotify(signValid, debugBypass bool, tradeStatus string, orderStatus uint8) epayNotifyDecision {
+	if !signValid && !debugBypass {
+		return epayNotifyDecisionRejectSign
+	}
+	if tradeStatus != "TRADE_SUCCESS" {
+		return epayNotifyDecisionAckTradeNotSuccess
+	}
+	if orderStatus == 5 {
+		return epayNotifyDecisionAckIdempotent
+	}
+	return epayNotifyDecisionProcess
+}
+
 type EPayNotifyLogic struct {
 	logger.Logger
 	ctx    *gin.Context
@@ -47,6 +89,8 @@ func (l *EPayNotifyLogic) EPayNotify(req *types.EPayNotifyRequest) error {
 	}
 	orderInfo, err := l.svcCtx.OrderModel.FindOneByOrderNo(l.ctx, req.OutTradeNo)
 	if err != nil {
+		// HIF-136 P02: order missing must propagate as error so EPay retries instead
+		// of being silently lost (was previously masked by a `return nil` further down).
 		l.Logger.Error("[EPayNotify] Find order failed", logger.Field("error", err.Error()), logger.Field("orderNo", req.OutTradeNo))
 		return errors.Wrapf(xerr.NewErrCode(xerr.OrderNotExist), "order not exist: %v", req.OutTradeNo)
 	}
@@ -65,17 +109,54 @@ func (l *EPayNotifyLogic) EPayNotify(req *types.EPayNotifyRequest) error {
 	}
 	// Verify sign
 	client := epay.NewClient(config.Pid, config.Url, config.Key, config.Type)
-	if !client.VerifySign(urlParamsToMap(l.ctx.Request.URL.RawQuery)) && !l.svcCtx.Config.Debug {
-		l.Logger.Error("[EPayNotify] Verify sign failed")
+	signValid := client.VerifySign(urlParamsToMap(l.ctx.Request.URL.RawQuery))
+
+	decision := evaluateEPayNotify(signValid, l.svcCtx.Config.Debug, req.TradeStatus, orderInfo.Status)
+	switch decision {
+	case epayNotifyDecisionRejectSign:
+		// HIF-136 P01: previously `return nil` here let EPay see 200 and stop retrying;
+		// caller still left order at status=1, which DeferCloseOrder then closed.
+		// Return error so handler responds non-200 and EPay retries.
+		l.Logger.Error("[EPayNotify] Verify sign failed",
+			logger.Field("order_no", req.OutTradeNo),
+			logger.Field("trade_no", req.TradeNo),
+			logger.Field("raw_query", l.ctx.Request.URL.RawQuery),
+		)
+		return errors.Wrapf(xerr.NewErrCode(xerr.SignatureInvalid), "verify sign failed: %v", req.OutTradeNo)
+	case epayNotifyDecisionAckTradeNotSuccess:
+		// User cancelled / gateway-side failure: ack 200 to stop retries, but keep
+		// the path observable under metric name `epay_notify_trade_not_success`.
+		l.Logger.Info("[EPayNotify] Trade status not success",
+			logger.Field("order_no", req.OutTradeNo),
+			logger.Field("trade_status", req.TradeStatus),
+			logger.Field("metric", epayNotifyTradeNotSuccess),
+		)
 		return nil
-	}
-	if req.TradeStatus != "TRADE_SUCCESS" {
-		l.Logger.Error("[EPayNotify] Trade status is not success", logger.Field("orderNo", req.OutTradeNo), logger.Field("tradeStatus", req.TradeStatus))
+	case epayNotifyDecisionAckIdempotent:
+		// Order already Finished — repeat callback is expected, ack with 200.
 		return nil
+	case epayNotifyDecisionProcess:
+		// fall through
 	}
-	if orderInfo.Status == 5 {
-		return nil
+
+	// HIF-136 P03: persist gateway trade_no BEFORE flipping status so post-mortems can
+	// reverse-lookup EPay flows to ppanel orders. Raw gorm write is acceptable here —
+	// the subsequent UpdateOrderStatus will invalidate the cache key (keys are by
+	// order_no / id, both stable across this field write).
+	if req.TradeNo != "" {
+		if err := l.svcCtx.DB.WithContext(l.ctx).
+			Model(&order.Order{}).
+			Where("order_no = ?", req.OutTradeNo).
+			Update("trade_no", req.TradeNo).Error; err != nil {
+			l.Logger.Error("[EPayNotify] Update trade_no failed",
+				logger.Field("error", err.Error()),
+				logger.Field("order_no", req.OutTradeNo),
+				logger.Field("trade_no", req.TradeNo),
+			)
+			return errors.Wrapf(err, "update trade_no failed: %v", req.OutTradeNo)
+		}
 	}
+
 	// Update order status
 	err = l.svcCtx.OrderModel.UpdateOrderStatus(l.ctx, req.OutTradeNo, 2)
 	if err != nil {
@@ -86,6 +167,7 @@ func (l *EPayNotifyLogic) EPayNotify(req *types.EPayNotifyRequest) error {
 		"[SubscriptionFlow] epay notify marked order as paid",
 		append(commonLogic.OrderTraceFields(orderInfo),
 			logger.Field("payment_platform", data.Platform),
+			logger.Field("trade_no", req.TradeNo),
 		)...,
 	)
 	// Create activate order task
@@ -0,0 +1,182 @@
+package notify
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"testing"
+
+	"github.com/DATA-DOG/go-sqlmock"
+	"github.com/perfect-panel/server/internal/model/order"
+	"gorm.io/driver/mysql"
+	"gorm.io/gorm"
+)
+
+// TestEvaluateEPayNotify_RejectsInvalidSign covers HIF-136 P01: sign invalid +
+// debug bypass off must return rejectSign so the handler responds non-200 and
+// EPay retries (was previously a silent `return nil` → 200 → no retry).
+func TestEvaluateEPayNotify_RejectsInvalidSign(t *testing.T) {
+	got := evaluateEPayNotify(false, false, "TRADE_SUCCESS", 1)
+	if got != epayNotifyDecisionRejectSign {
+		t.Fatalf("evaluateEPayNotify(invalid sign): got %v want %v", got, epayNotifyDecisionRejectSign)
+	}
+}
+
+// TestEvaluateEPayNotify_DebugBypassAllowsInvalidSign documents the debug-mode
+// escape hatch the issue calls out: production runs with Debug=false so this
+// branch is never taken in prod, but local/dev should still flow through.
+func TestEvaluateEPayNotify_DebugBypassAllowsInvalidSign(t *testing.T) {
+	got := evaluateEPayNotify(false, true, "TRADE_SUCCESS", 1)
+	if got != epayNotifyDecisionProcess {
+		t.Fatalf("evaluateEPayNotify(invalid sign + debug): got %v want %v", got, epayNotifyDecisionProcess)
+	}
+}
+
+// TestEvaluateEPayNotify_TradeNotSuccess covers the user-cancelled / gateway-failure
+// branch: behaviour unchanged (return nil → 200), but caller must now emit the
+// `epay_notify_trade_not_success` metric-named log instead of an Error-level one.
+func TestEvaluateEPayNotify_TradeNotSuccess(t *testing.T) {
+	tests := []string{"TRADE_FAILED", "WAIT_BUYER_PAY", ""}
+	for _, ts := range tests {
+		t.Run(ts, func(t *testing.T) {
+			got := evaluateEPayNotify(true, false, ts, 1)
+			if got != epayNotifyDecisionAckTradeNotSuccess {
+				t.Fatalf("evaluateEPayNotify(trade_status=%q): got %v want %v",
+					ts, got, epayNotifyDecisionAckTradeNotSuccess)
+			}
+		})
+	}
+}
+
+// TestEvaluateEPayNotify_IdempotentForFinishedOrder covers the only legitimate
+// `return nil` short-circuit retained by HIF-136: duplicate callback for an
+// already Finished (status=5) order is acknowledged with 200 instead of being
+// re-processed.
+func TestEvaluateEPayNotify_IdempotentForFinishedOrder(t *testing.T) {
+	got := evaluateEPayNotify(true, false, "TRADE_SUCCESS", 5)
+	if got != epayNotifyDecisionAckIdempotent {
+		t.Fatalf("evaluateEPayNotify(status=5): got %v want %v", got, epayNotifyDecisionAckIdempotent)
+	}
+}
+
+// TestEvaluateEPayNotify_HappyPath covers the normal success branch: valid sign,
+// trade_status=TRADE_SUCCESS, order not yet Finished → proceed to write trade_no
+// + flip status + enqueue activation.
+func TestEvaluateEPayNotify_HappyPath(t *testing.T) {
+	statuses := []uint8{1, 2, 3, 4} // anything but Finished(5)
+	for _, s := range statuses {
+		got := evaluateEPayNotify(true, false, "TRADE_SUCCESS", s)
+		if got != epayNotifyDecisionProcess {
+			t.Fatalf("evaluateEPayNotify(status=%d): got %v want %v", s, got, epayNotifyDecisionProcess)
+		}
+	}
+}
+
+// TestEvaluateEPayNotify_SignTakesPrecedenceOverIdempotency guards against a
+// regression where a duplicate callback with a forged signature gets quietly
+// acked because status==5 was checked before sign.
+func TestEvaluateEPayNotify_SignTakesPrecedenceOverIdempotency(t *testing.T) {
+	got := evaluateEPayNotify(false, false, "TRADE_SUCCESS", 5)
+	if got != epayNotifyDecisionRejectSign {
+		t.Fatalf("evaluateEPayNotify(invalid sign + status=5): got %v want %v",
+			got, epayNotifyDecisionRejectSign)
+	}
+}
+
+// TestUrlParamsToMap verifies the helper used to feed VerifySign — collapses
+// each query parameter to its first value and treats absent params as missing.
+func TestUrlParamsToMap(t *testing.T) {
+	got := urlParamsToMap("pid=1001&out_trade_no=ORD-1&trade_no=EPAY-9&sign=abc&trade_status=TRADE_SUCCESS")
+	want := map[string]string{
+		"pid":          "1001",
+		"out_trade_no": "ORD-1",
+		"trade_no":     "EPAY-9",
+		"sign":         "abc",
+		"trade_status": "TRADE_SUCCESS",
+	}
+	if len(got) != len(want) {
+		t.Fatalf("urlParamsToMap len = %d want %d (got=%v)", len(got), len(want), got)
+	}
+	for k, v := range want {
+		if got[k] != v {
+			t.Fatalf("urlParamsToMap[%q] = %q want %q", k, got[k], v)
+		}
+	}
+}
+
+// TestEPayNotify_TradeNoRawWrite verifies HIF-136 P03 at the SQL boundary: the
+// raw gorm write hits the `order` table with the exact `trade_no` from the
+// EPay request, scoped by `order_no`, and surfaces driver errors back to the
+// caller (so they propagate as non-200 and EPay retries).
+func TestEPayNotify_TradeNoRawWrite(t *testing.T) {
+	db, mock, cleanup := newEPayNotifyTestDB(t)
+	defer cleanup()
+
+	const (
+		orderNo = "202606010001"
+		tradeNo = "EPAY-202606010001"
+	)
+
+	mock.ExpectBegin()
+	mock.ExpectExec("UPDATE `order` SET `trade_no`").
+		WithArgs(tradeNo, sqlmock.AnyArg(), orderNo).
+		WillReturnResult(sqlmock.NewResult(0, 1))
+	mock.ExpectCommit()
+
+	err := db.WithContext(context.Background()).
+		Model(&order.Order{}).
+		Where("order_no = ?", orderNo).
+		Update("trade_no", tradeNo).Error
+	if err != nil {
+		t.Fatalf("raw trade_no update: %v", err)
+	}
+	if err := mock.ExpectationsWereMet(); err != nil {
+		t.Fatalf("unmet sql expectations: %v", err)
+	}
+}
+
+// TestEPayNotify_TradeNoRawWritePropagatesError ensures a DB-side failure during
+// the trade_no backfill is not swallowed — caller returns the error so EPay
+// retries instead of silently flipping status without trade_no being written.
+func TestEPayNotify_TradeNoRawWritePropagatesError(t *testing.T) {
+	db, mock, cleanup := newEPayNotifyTestDB(t)
+	defer cleanup()
+
+	mock.ExpectBegin()
+	mock.ExpectExec("UPDATE `order` SET `trade_no`").
+		WillReturnError(fmt.Errorf("deadlock detected"))
+	mock.ExpectRollback()
+
+	err := db.WithContext(context.Background()).
+		Model(&order.Order{}).
+		Where("order_no = ?", "ORD-2").
+		Update("trade_no", "EPAY-2").Error
+	if err == nil {
+		t.Fatalf("expected error from raw trade_no update, got nil")
+	}
+	if err := mock.ExpectationsWereMet(); err != nil {
+		t.Fatalf("unmet sql expectations: %v", err)
+	}
+}
+
+func newEPayNotifyTestDB(t *testing.T) (*gorm.DB, sqlmock.Sqlmock, func()) {
+	t.Helper()
+
+	sqlDB, mock, err := sqlmock.New(sqlmock.QueryMatcherOption(sqlmock.QueryMatcherFunc(func(expectedSQL, actualSQL string) error {
+		if strings.Contains(actualSQL, expectedSQL) {
+			return nil
+		}
+		return fmt.Errorf("actual sql %q does not contain %q", actualSQL, expectedSQL)
+	})))
+	if err != nil {
+		t.Fatalf("create sqlmock: %v", err)
+	}
+	db, err := gorm.Open(mysql.New(mysql.Config{Conn: sqlDB, SkipInitializeWithVersion: true}), &gorm.Config{})
+	if err != nil {
+		_ = sqlDB.Close()
+		t.Fatalf("open gorm db: %v", err)
+	}
+	return db, mock, func() {
+		_ = sqlDB.Close()
+	}
+}