Introduce a sentinel ErrOrderNotFound in the payment service layer so the
webhook handler can distinguish "the out_trade_no does not exist in our DB"
from other fulfillment failures, and downgrade the former to a WARN log +
success response.
Background
- Providers (Stripe, Alipay, Wxpay, EasyPay, ...) retry webhooks whenever
we answer non-2xx. When a webhook endpoint is misconfigured (e.g. a
foreign environment points at us) or our orders table has been wiped,
we return 500 forever and the provider retries for days, spamming logs.
- The old code also collapsed "order not found" and "DB query failed" into
the same branch — a DB blip would be reported as "order not found" and
swallowed.
Service layer (payment_fulfillment.go)
- Add `var ErrOrderNotFound = errors.New("payment order not found")`.
- In HandlePaymentNotification, distinguish the two error paths:
* dbent.IsNotFound(err) → wrap with ErrOrderNotFound so callers can
errors.Is(...) it.
* anything else → wrap the original err with %w so it still bubbles up
as 500 and the provider retries (DB hiccup should be retried).
Handler layer (payment_webhook_handler.go)
- Before returning 500, check errors.Is(err, service.ErrOrderNotFound):
emit a WARN (with provider / outTradeNo / tradeNo for discoverability),
then call writeSuccessResponse so the provider sees its expected 2xx
body (Stripe empty body / Wxpay JSON / others "success").
- Other errors retain the existing 500 behavior.
Monitoring note: because this path now swallows unknown-order webhooks
silently from the provider's perspective, the WARN log line is the only
signal. Alert on "unknown order, acking to stop retries" if you want
visibility into misrouted webhooks or accidental data loss.
404 lines
15 KiB
Go
404 lines
15 KiB
Go
package service
|
|
|
|
import (
|
|
"context"
|
|
"errors"
|
|
"fmt"
|
|
"log/slog"
|
|
"math"
|
|
"strconv"
|
|
"strings"
|
|
"time"
|
|
|
|
dbent "github.com/Wei-Shaw/sub2api/ent"
|
|
"github.com/Wei-Shaw/sub2api/ent/paymentauditlog"
|
|
"github.com/Wei-Shaw/sub2api/ent/paymentorder"
|
|
"github.com/Wei-Shaw/sub2api/internal/payment"
|
|
infraerrors "github.com/Wei-Shaw/sub2api/internal/pkg/errors"
|
|
)
|
|
|
|
// ErrOrderNotFound is returned by HandlePaymentNotification when the webhook
|
|
// references an out_trade_no that does not exist in our DB. Callers (webhook
|
|
// handlers) should treat this as a terminal, non-retryable condition and still
|
|
// respond with a 2xx success to the provider — otherwise the provider will keep
|
|
// retrying forever (e.g. when a foreign environment's webhook endpoint is
|
|
// misconfigured to point at us, or when our orders table has been wiped).
|
|
var ErrOrderNotFound = errors.New("payment order not found")
|
|
|
|
// --- Payment Notification & Fulfillment ---
|
|
|
|
func (s *PaymentService) HandlePaymentNotification(ctx context.Context, n *payment.PaymentNotification, pk string) error {
|
|
if n.Status != payment.NotificationStatusSuccess {
|
|
return nil
|
|
}
|
|
// Look up order by out_trade_no (the external order ID we sent to the provider)
|
|
order, err := s.entClient.PaymentOrder.Query().Where(paymentorder.OutTradeNo(n.OrderID)).Only(ctx)
|
|
if err != nil {
|
|
// Fallback only for true legacy "sub2_N" DB-ID payloads when the
|
|
// current out_trade_no lookup genuinely did not find an order.
|
|
if oid, ok := parseLegacyPaymentOrderID(n.OrderID, err); ok {
|
|
return s.confirmPayment(ctx, oid, n.TradeNo, n.Amount, pk, n.Metadata)
|
|
}
|
|
if dbent.IsNotFound(err) {
|
|
return fmt.Errorf("%w: out_trade_no=%s", ErrOrderNotFound, n.OrderID)
|
|
}
|
|
return fmt.Errorf("lookup order failed for out_trade_no %s: %w", n.OrderID, err)
|
|
}
|
|
return s.confirmPayment(ctx, order.ID, n.TradeNo, n.Amount, pk, n.Metadata)
|
|
}
|
|
|
|
func parseLegacyPaymentOrderID(orderID string, lookupErr error) (int64, bool) {
|
|
if !dbent.IsNotFound(lookupErr) {
|
|
return 0, false
|
|
}
|
|
orderID = strings.TrimSpace(orderID)
|
|
if !strings.HasPrefix(orderID, orderIDPrefix) {
|
|
return 0, false
|
|
}
|
|
trimmed := strings.TrimPrefix(orderID, orderIDPrefix)
|
|
if trimmed == "" || trimmed == orderID {
|
|
return 0, false
|
|
}
|
|
oid, err := strconv.ParseInt(trimmed, 10, 64)
|
|
if err != nil || oid <= 0 {
|
|
return 0, false
|
|
}
|
|
return oid, true
|
|
}
|
|
|
|
func (s *PaymentService) confirmPayment(ctx context.Context, oid int64, tradeNo string, paid float64, pk string, metadata map[string]string) error {
|
|
o, err := s.entClient.PaymentOrder.Get(ctx, oid)
|
|
if err != nil {
|
|
slog.Error("order not found", "orderID", oid)
|
|
return nil
|
|
}
|
|
instanceProviderKey := ""
|
|
if inst, instErr := s.getOrderProviderInstance(ctx, o); instErr == nil && inst != nil {
|
|
instanceProviderKey = inst.ProviderKey
|
|
}
|
|
expectedProviderKey := expectedNotificationProviderKeyForOrder(s.registry, o, instanceProviderKey)
|
|
if expectedProviderKey != "" && strings.TrimSpace(pk) != "" && !strings.EqualFold(expectedProviderKey, strings.TrimSpace(pk)) {
|
|
s.writeAuditLog(ctx, o.ID, "PAYMENT_PROVIDER_MISMATCH", pk, map[string]any{
|
|
"expectedProvider": expectedProviderKey,
|
|
"actualProvider": pk,
|
|
"tradeNo": tradeNo,
|
|
})
|
|
return fmt.Errorf("provider mismatch: expected %s, got %s", expectedProviderKey, pk)
|
|
}
|
|
if err := validateProviderNotificationMetadata(o, pk, metadata); err != nil {
|
|
s.writeAuditLog(ctx, o.ID, "PAYMENT_PROVIDER_METADATA_MISMATCH", pk, map[string]any{
|
|
"detail": err.Error(),
|
|
"tradeNo": tradeNo,
|
|
})
|
|
return err
|
|
}
|
|
if !isValidProviderAmount(paid) {
|
|
s.writeAuditLog(ctx, o.ID, "PAYMENT_INVALID_AMOUNT", pk, map[string]any{
|
|
"expected": o.PayAmount,
|
|
"paid": paid,
|
|
"tradeNo": tradeNo,
|
|
})
|
|
return fmt.Errorf("invalid paid amount from provider: %v", paid)
|
|
}
|
|
if math.Abs(paid-o.PayAmount) > amountToleranceCNY {
|
|
s.writeAuditLog(ctx, o.ID, "PAYMENT_AMOUNT_MISMATCH", pk, map[string]any{"expected": o.PayAmount, "paid": paid, "tradeNo": tradeNo})
|
|
return fmt.Errorf("amount mismatch: expected %.2f, got %.2f", o.PayAmount, paid)
|
|
}
|
|
return s.toPaid(ctx, o, tradeNo, paid, pk)
|
|
}
|
|
|
|
func isValidProviderAmount(amount float64) bool {
|
|
return amount > 0 && !math.IsNaN(amount) && !math.IsInf(amount, 0)
|
|
}
|
|
|
|
func validateProviderNotificationMetadata(order *dbent.PaymentOrder, providerKey string, metadata map[string]string) error {
|
|
return validateProviderSnapshotMetadata(order, providerKey, metadata)
|
|
}
|
|
|
|
func expectedNotificationProviderKey(registry *payment.Registry, orderPaymentType string, orderProviderKey string, instanceProviderKey string) string {
|
|
if key := strings.TrimSpace(instanceProviderKey); key != "" {
|
|
return key
|
|
}
|
|
if key := strings.TrimSpace(orderProviderKey); key != "" {
|
|
return key
|
|
}
|
|
if registry != nil {
|
|
if key := strings.TrimSpace(registry.GetProviderKey(payment.PaymentType(orderPaymentType))); key != "" {
|
|
return key
|
|
}
|
|
}
|
|
return strings.TrimSpace(orderPaymentType)
|
|
}
|
|
|
|
func (s *PaymentService) toPaid(ctx context.Context, o *dbent.PaymentOrder, tradeNo string, paid float64, pk string) error {
|
|
previousStatus := o.Status
|
|
now := time.Now()
|
|
grace := now.Add(-paymentGraceMinutes * time.Minute)
|
|
c, err := s.entClient.PaymentOrder.Update().Where(
|
|
paymentorder.IDEQ(o.ID),
|
|
paymentorder.Or(
|
|
paymentorder.StatusEQ(OrderStatusPending),
|
|
paymentorder.StatusEQ(OrderStatusCancelled),
|
|
paymentorder.And(
|
|
paymentorder.StatusEQ(OrderStatusExpired),
|
|
paymentorder.UpdatedAtGTE(grace),
|
|
),
|
|
),
|
|
).SetStatus(OrderStatusPaid).SetPayAmount(paid).SetPaymentTradeNo(tradeNo).SetPaidAt(now).ClearFailedAt().ClearFailedReason().Save(ctx)
|
|
if err != nil {
|
|
return fmt.Errorf("update to PAID: %w", err)
|
|
}
|
|
if c == 0 {
|
|
return s.alreadyProcessed(ctx, o)
|
|
}
|
|
if previousStatus == OrderStatusCancelled || previousStatus == OrderStatusExpired {
|
|
slog.Info("order recovered from webhook payment success",
|
|
"orderID", o.ID,
|
|
"previousStatus", previousStatus,
|
|
"tradeNo", tradeNo,
|
|
"provider", pk,
|
|
)
|
|
s.writeAuditLog(ctx, o.ID, "ORDER_RECOVERED", pk, map[string]any{
|
|
"previous_status": previousStatus,
|
|
"tradeNo": tradeNo,
|
|
"paidAmount": paid,
|
|
"reason": "webhook payment success received after order " + previousStatus,
|
|
})
|
|
}
|
|
s.writeAuditLog(ctx, o.ID, "ORDER_PAID", pk, map[string]any{"tradeNo": tradeNo, "paidAmount": paid})
|
|
return s.executeFulfillment(ctx, o.ID)
|
|
}
|
|
|
|
func (s *PaymentService) alreadyProcessed(ctx context.Context, o *dbent.PaymentOrder) error {
|
|
cur, err := s.entClient.PaymentOrder.Get(ctx, o.ID)
|
|
if err != nil {
|
|
return nil
|
|
}
|
|
switch cur.Status {
|
|
case OrderStatusCompleted, OrderStatusRefunded:
|
|
return nil
|
|
case OrderStatusFailed:
|
|
return s.executeFulfillment(ctx, o.ID)
|
|
case OrderStatusPaid, OrderStatusRecharging:
|
|
return fmt.Errorf("order %d is being processed", o.ID)
|
|
case OrderStatusExpired:
|
|
slog.Warn("webhook payment success for expired order beyond grace period",
|
|
"orderID", o.ID,
|
|
"status", cur.Status,
|
|
"updatedAt", cur.UpdatedAt,
|
|
)
|
|
s.writeAuditLog(ctx, o.ID, "PAYMENT_AFTER_EXPIRY", "system", map[string]any{
|
|
"status": cur.Status,
|
|
"updatedAt": cur.UpdatedAt,
|
|
"reason": "payment arrived after expiry grace period",
|
|
})
|
|
return nil
|
|
default:
|
|
return nil
|
|
}
|
|
}
|
|
|
|
func (s *PaymentService) executeFulfillment(ctx context.Context, oid int64) error {
|
|
o, err := s.entClient.PaymentOrder.Get(ctx, oid)
|
|
if err != nil {
|
|
return fmt.Errorf("get order: %w", err)
|
|
}
|
|
if o.OrderType == payment.OrderTypeSubscription {
|
|
return s.ExecuteSubscriptionFulfillment(ctx, oid)
|
|
}
|
|
return s.ExecuteBalanceFulfillment(ctx, oid)
|
|
}
|
|
|
|
func (s *PaymentService) ExecuteBalanceFulfillment(ctx context.Context, oid int64) error {
|
|
o, err := s.entClient.PaymentOrder.Get(ctx, oid)
|
|
if err != nil {
|
|
return infraerrors.NotFound("NOT_FOUND", "order not found")
|
|
}
|
|
if o.Status == OrderStatusCompleted {
|
|
return nil
|
|
}
|
|
if psIsRefundStatus(o.Status) {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "refund-related order cannot fulfill")
|
|
}
|
|
if o.Status != OrderStatusPaid && o.Status != OrderStatusFailed {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "order cannot fulfill in status "+o.Status)
|
|
}
|
|
c, err := s.entClient.PaymentOrder.Update().Where(paymentorder.IDEQ(oid), paymentorder.StatusIn(OrderStatusPaid, OrderStatusFailed)).SetStatus(OrderStatusRecharging).Save(ctx)
|
|
if err != nil {
|
|
return fmt.Errorf("lock: %w", err)
|
|
}
|
|
if c == 0 {
|
|
return nil
|
|
}
|
|
if err := s.doBalance(ctx, o); err != nil {
|
|
s.markFailed(ctx, oid, err)
|
|
return err
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// redeemAction represents the idempotency decision for balance fulfillment.
|
|
type redeemAction int
|
|
|
|
const (
|
|
// redeemActionCreate: code does not exist — create it, then redeem.
|
|
redeemActionCreate redeemAction = iota
|
|
// redeemActionRedeem: code exists but is unused — skip creation, redeem only.
|
|
redeemActionRedeem
|
|
// redeemActionSkipCompleted: code exists and is already used — skip to mark completed.
|
|
redeemActionSkipCompleted
|
|
)
|
|
|
|
// resolveRedeemAction decides the idempotency action based on an existing redeem code lookup.
|
|
// existing is the result of GetByCode; lookupErr is the error from that call.
|
|
func resolveRedeemAction(existing *RedeemCode, lookupErr error) redeemAction {
|
|
if existing == nil || lookupErr != nil {
|
|
return redeemActionCreate
|
|
}
|
|
if existing.IsUsed() {
|
|
return redeemActionSkipCompleted
|
|
}
|
|
return redeemActionRedeem
|
|
}
|
|
|
|
func (s *PaymentService) doBalance(ctx context.Context, o *dbent.PaymentOrder) error {
|
|
// Idempotency: check if redeem code already exists (from a previous partial run)
|
|
existing, lookupErr := s.redeemService.GetByCode(ctx, o.RechargeCode)
|
|
action := resolveRedeemAction(existing, lookupErr)
|
|
|
|
switch action {
|
|
case redeemActionSkipCompleted:
|
|
// Code already created and redeemed — just mark completed
|
|
return s.markCompleted(ctx, o, "RECHARGE_SUCCESS")
|
|
case redeemActionCreate:
|
|
rc := &RedeemCode{Code: o.RechargeCode, Type: RedeemTypeBalance, Value: o.Amount, Status: StatusUnused}
|
|
if err := s.redeemService.CreateCode(ctx, rc); err != nil {
|
|
return fmt.Errorf("create redeem code: %w", err)
|
|
}
|
|
case redeemActionRedeem:
|
|
// Code exists but unused — skip creation, proceed to redeem
|
|
}
|
|
if _, err := s.redeemService.Redeem(ctx, o.UserID, o.RechargeCode); err != nil {
|
|
return fmt.Errorf("redeem balance: %w", err)
|
|
}
|
|
return s.markCompleted(ctx, o, "RECHARGE_SUCCESS")
|
|
}
|
|
|
|
func (s *PaymentService) markCompleted(ctx context.Context, o *dbent.PaymentOrder, auditAction string) error {
|
|
now := time.Now()
|
|
_, err := s.entClient.PaymentOrder.Update().Where(paymentorder.IDEQ(o.ID), paymentorder.StatusEQ(OrderStatusRecharging)).SetStatus(OrderStatusCompleted).SetCompletedAt(now).Save(ctx)
|
|
if err != nil {
|
|
return fmt.Errorf("mark completed: %w", err)
|
|
}
|
|
s.writeAuditLog(ctx, o.ID, auditAction, "system", map[string]any{
|
|
"rechargeCode": o.RechargeCode,
|
|
"creditedAmount": o.Amount,
|
|
"payAmount": o.PayAmount,
|
|
})
|
|
return nil
|
|
}
|
|
|
|
func (s *PaymentService) ExecuteSubscriptionFulfillment(ctx context.Context, oid int64) error {
|
|
o, err := s.entClient.PaymentOrder.Get(ctx, oid)
|
|
if err != nil {
|
|
return infraerrors.NotFound("NOT_FOUND", "order not found")
|
|
}
|
|
if o.Status == OrderStatusCompleted {
|
|
return nil
|
|
}
|
|
if psIsRefundStatus(o.Status) {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "refund-related order cannot fulfill")
|
|
}
|
|
if o.Status != OrderStatusPaid && o.Status != OrderStatusFailed {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "order cannot fulfill in status "+o.Status)
|
|
}
|
|
if o.SubscriptionGroupID == nil || o.SubscriptionDays == nil {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "missing subscription info")
|
|
}
|
|
c, err := s.entClient.PaymentOrder.Update().Where(paymentorder.IDEQ(oid), paymentorder.StatusIn(OrderStatusPaid, OrderStatusFailed)).SetStatus(OrderStatusRecharging).Save(ctx)
|
|
if err != nil {
|
|
return fmt.Errorf("lock: %w", err)
|
|
}
|
|
if c == 0 {
|
|
return nil
|
|
}
|
|
if err := s.doSub(ctx, o); err != nil {
|
|
s.markFailed(ctx, oid, err)
|
|
return err
|
|
}
|
|
return nil
|
|
}
|
|
|
|
func (s *PaymentService) doSub(ctx context.Context, o *dbent.PaymentOrder) error {
|
|
gid := *o.SubscriptionGroupID
|
|
days := *o.SubscriptionDays
|
|
g, err := s.groupRepo.GetByID(ctx, gid)
|
|
if err != nil || g.Status != payment.EntityStatusActive {
|
|
return fmt.Errorf("group %d no longer exists or inactive", gid)
|
|
}
|
|
// Idempotency: check audit log to see if subscription was already assigned.
|
|
// Prevents double-extension on retry after markCompleted fails.
|
|
if s.hasAuditLog(ctx, o.ID, "SUBSCRIPTION_SUCCESS") {
|
|
slog.Info("subscription already assigned for order, skipping", "orderID", o.ID, "groupID", gid)
|
|
return s.markCompleted(ctx, o, "SUBSCRIPTION_SUCCESS")
|
|
}
|
|
orderNote := fmt.Sprintf("payment order %d", o.ID)
|
|
_, _, err = s.subscriptionSvc.AssignOrExtendSubscription(ctx, &AssignSubscriptionInput{UserID: o.UserID, GroupID: gid, ValidityDays: days, AssignedBy: 0, Notes: orderNote})
|
|
if err != nil {
|
|
return fmt.Errorf("assign subscription: %w", err)
|
|
}
|
|
return s.markCompleted(ctx, o, "SUBSCRIPTION_SUCCESS")
|
|
}
|
|
|
|
func (s *PaymentService) hasAuditLog(ctx context.Context, orderID int64, action string) bool {
|
|
oid := strconv.FormatInt(orderID, 10)
|
|
c, _ := s.entClient.PaymentAuditLog.Query().
|
|
Where(paymentauditlog.OrderIDEQ(oid), paymentauditlog.ActionEQ(action)).
|
|
Limit(1).Count(ctx)
|
|
return c > 0
|
|
}
|
|
|
|
func (s *PaymentService) markFailed(ctx context.Context, oid int64, cause error) {
|
|
now := time.Now()
|
|
r := psErrMsg(cause)
|
|
// Only mark FAILED if still in RECHARGING state — prevents overwriting
|
|
// a COMPLETED order when markCompleted failed but fulfillment succeeded.
|
|
c, e := s.entClient.PaymentOrder.Update().
|
|
Where(paymentorder.IDEQ(oid), paymentorder.StatusEQ(OrderStatusRecharging)).
|
|
SetStatus(OrderStatusFailed).SetFailedAt(now).SetFailedReason(r).Save(ctx)
|
|
if e != nil {
|
|
slog.Error("mark FAILED", "orderID", oid, "error", e)
|
|
}
|
|
if c > 0 {
|
|
s.writeAuditLog(ctx, oid, "FULFILLMENT_FAILED", "system", map[string]any{"reason": r})
|
|
}
|
|
}
|
|
|
|
func (s *PaymentService) RetryFulfillment(ctx context.Context, oid int64) error {
|
|
o, err := s.entClient.PaymentOrder.Get(ctx, oid)
|
|
if err != nil {
|
|
return infraerrors.NotFound("NOT_FOUND", "order not found")
|
|
}
|
|
if o.PaidAt == nil {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "order is not paid")
|
|
}
|
|
if psIsRefundStatus(o.Status) {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "refund-related order cannot retry")
|
|
}
|
|
if o.Status == OrderStatusRecharging {
|
|
return infraerrors.Conflict("CONFLICT", "order is being processed")
|
|
}
|
|
if o.Status == OrderStatusCompleted {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "order already completed")
|
|
}
|
|
if o.Status != OrderStatusFailed && o.Status != OrderStatusPaid {
|
|
return infraerrors.BadRequest("INVALID_STATUS", "only paid and failed orders can retry")
|
|
}
|
|
_, err = s.entClient.PaymentOrder.Update().Where(paymentorder.IDEQ(oid), paymentorder.StatusIn(OrderStatusFailed, OrderStatusPaid)).SetStatus(OrderStatusPaid).ClearFailedAt().ClearFailedReason().Save(ctx)
|
|
if err != nil {
|
|
return fmt.Errorf("reset for retry: %w", err)
|
|
}
|
|
s.writeAuditLog(ctx, oid, "RECHARGE_RETRY", "admin", map[string]any{"detail": "admin manual retry"})
|
|
return s.executeFulfillment(ctx, oid)
|
|
}
|