diff --git a/backend/handlers/payments/sweep.go b/backend/handlers/payments/sweep.go index 845c1f9..a4e773b 100644 --- a/backend/handlers/payments/sweep.go +++ b/backend/handlers/payments/sweep.go @@ -16,6 +16,7 @@ import ( "crussell/clock" "crussell/db" + "crussell/internal/adminnotify" "crussell/internal/square" "github.com/jackc/pgx/v5" @@ -50,6 +51,17 @@ import ( // Only online/till card payments can be pending — cash/giftcard/on_the_house // are committed synchronously and never enter this state. Both the payments // table and till_sales carry pending card-sale rows and are swept here. +// +// CLOCK-SOURCE CONTRACT (M3): EVERY age-guard cutoff in this package is +// computed from clock.Now() (the single wall-clock source) — never from a DB +// NOW()-derived comparison. The DB's NOW() is used only at WRITE time (the +// created_at/updated_at rows this sweep reads); the sweep's cutoffs are +// computed in Go from clock.Now() and passed into the SQL as parameters, so a +// Go-side comparison can never mix a DB-computed cutoff with a Go-computed +// one. This matters at the 23h/24h boundary: Square's idempotency-key +// retention (~24h) is compared against the DB-stored created_at, and using one +// consistent source prevents the decision from flipping on the skew between +// two independent clocks. const stalePendingPaymentAge = 24 * time.Hour // stalePendingKeyedAge is how old a pending row with a stored idempotency key @@ -263,7 +275,7 @@ func sweepStaleRows(ctx context.Context, table string, cutoff time.Time) (resolv // UPDATE) and refuse on a cancelled booking. Rows with no // booking (gift-card purchases, till_sales) are never gated. if table == "payments" { - switch gateStalePaymentRescueOnBooking(ctx, r) { + switch gateStalePaymentRescueOnBooking(ctx, r, r.SquarePaymentID) { case staleBookingGateRefused: resolved++ continue @@ -403,7 +415,7 @@ func sweepKeyedStaleRows(ctx context.Context, table string, cutoff time.Time) (r // Square reports COMPLETED must never be completed on a booking // that was cancelled during the pending window. if table == "payments" { - switch gateStalePaymentRescueOnBooking(ctx, r) { + switch gateStalePaymentRescueOnBooking(ctx, r, sqPayID) { case staleBookingGateRefused: resolved++ continue @@ -646,6 +658,13 @@ func rescueStaleRowCompletedTx(ctx context.Context, table, id, squarePaymentID s if len(records) > 0 { applyStaleRescueRecords(ctx, tx, r, records) } + if table == "till_sales" { + // M5: the synchronous till-completion path (GetTillCheckoutStatus) + // applies VAT via ApplyVATToTillSale; a sweep rescue must do the same or + // the rescued sale silently drops out of VAT reporting. The SQL function + // is idempotent (guarded on vat_amount IS NULL) inside the same tx. + ApplyVATToTillSale(ctx, tx, r.ID) + } if cErr := tx.Commit(ctx); cErr != nil { log.Printf("Failed to commit rescue of stale pending %s row %s: %v", table, id, cErr) @@ -731,22 +750,26 @@ func applyStaleRescueRecords(ctx context.Context, tx pgx.Tx, r staleRow, records amount = $1, payment_type = $2, fees = $3, - is_vat_applicable = FALSE, - vat_rate = NULL, - vat_amount = NULL, - net_amount = NULL, updated_at = NOW() WHERE id = $4 `, records[0].Amount, records[0].PaymentType, records[0].Fees, r.ID); upErr != nil { log.Printf("MEDIUM-3: failed to align rescued payment %s to its split primary (%v) — manual reconciliation recommended", r.ID, upErr) return } + // M5: the align UPDATE used to NULL the VAT fields, dropping a rescued + // charge out of VAT reporting. The synchronous post-charge path applies VAT + // per record (ApplyVATToBookingPayment); the sweep re-applies it after the + // align. apply_vat_to_payment is idempotent (guarded on vat_amount IS NULL) + // and skips discount/on_the_house/tip rows internally. + ApplyVATToBookingPayment(ctx, tx, r.ID) svc := NewPaymentService() for _, rec := range records[1:] { - if _, cErr := svc.CreatePaymentRecordTx(ctx, tx, rec, nil); cErr != nil { + pid, cErr := svc.CreatePaymentRecordTx(ctx, tx, rec, nil) + if cErr != nil { log.Printf("MEDIUM-3: failed to insert rescue split record for payment %s (%v) — manual reconciliation recommended", r.ID, cErr) return } + ApplyVATToBookingPayment(ctx, tx, pid) } if bookingIsFullyPaid(ctx, tx, *r.BookingID) { completeActiveBookingFromPayment(ctx, tx, *r.BookingID) @@ -779,13 +802,20 @@ const ( // The booking status is re-read FOR UPDATE inside a transaction so the // decision serializes against a concurrent cancellation (C5 pattern, mirrors // recordTerminalPaymentTx). On a cancelled/lapsed/no-show booking the payment -// row is marked FAILED (not completed) and a critical admin notification is -// raised, atomically with the decision, so an operator refunds the customer -// manually. A booking whose status cannot be read is never completed — the row -// is left pending for the next sweep run. Rows with no booking (till_sales; -// gift-card purchases are diverted by the callers before this helper) are -// never gated. -func gateStalePaymentRescueOnBooking(ctx context.Context, r staleRow) staleBookingGate { +// row is marked FAILED (not completed) and — M2 — a pending cancellation +// refund row is AUTO-CREATED for the full stranded charge (mirroring +// ProcessCancellationRefundTx's record shape and origin) so the pending-refund +// sweep (SweepPendingSquareRefunds → processChargeGroup) issues the Square +// refund automatically: previously the charge was only failed + admin-notified +// and the customer stayed charged with NO automatic refund row. The square +// payment id (authoritative — from the by-id reconcile, or the replay result +// on the keyed path) is written onto the row when it is missing, because the +// refund sweep refunds by square_payment_id. A critical admin notification is +// still raised so the operator sees the auto-refunded stranded charge. A +// booking whose status cannot be read is never completed — the row is left +// pending for the next sweep run. Rows with no booking (till_sales; gift-card +// purchases are diverted by the callers before this helper) are never gated. +func gateStalePaymentRescueOnBooking(ctx context.Context, r staleRow, squarePaymentID string) staleBookingGate { if r.BookingID == nil { return staleBookingGateAllowed } @@ -817,23 +847,42 @@ func gateStalePaymentRescueOnBooking(ctx context.Context, r staleRow) staleBooki } // Cancelled / lapsed / no-show booking: completing the payment would // charge a customer for a booking the cancellation flow already closed, - // with NO automatic refund. Mark the row FAILED (not completed) and alert - // ops so an operator refunds the customer manually. + // with NO automatic refund. Mark the row FAILED (not completed) so the + // same-key retry can never reuse it, and (M2) auto-create the refund row + // for the full stranded charge. tag, upErr := tx.Exec(ctx, ` - UPDATE `+pgx.Identifier{"payments"}.Sanitize()+` SET status = 'failed', updated_at = NOW() + UPDATE `+pgx.Identifier{"payments"}.Sanitize()+` + SET status = 'failed', square_payment_id = COALESCE(square_payment_id, $2), updated_at = NOW() WHERE id = $1 AND status = 'pending' - `, r.ID) + `, r.ID, squarePaymentID) if upErr != nil { log.Printf("CRITICAL: Square payment for stale pending row %s is COMPLETED but booking %s is %q — marking the row failed errored (%v) — MANUAL RECONCILIATION REQUIRED", r.ID, *r.BookingID, status, upErr) return staleBookingGateUnknown } + // M2: a refund row for the full stranded charge. Same shape and origin + // ('cancellation') ProcessCancellationRefundTx records, so the pending + // Square refund sweep (SweepPendingSquareRefunds) aggregates and issues it + // at Square. The deterministic key mirrors the cancellation path + // (paymentID + "-square-" + amount pence) and the UNIQUE conflict guard + // makes a re-run idempotent. created_by falls back to the row's payer. + if int(tag.RowsAffected()) > 0 && r.AmountPence > 0 { + if _, rfErr := tx.Exec(ctx, ` + INSERT INTO refunds (payment_id, booking_id, amount, status, reason, idempotency_key, created_by, created_at, origin) + VALUES ($1, $2, $3, 'pending', $4, $5, $6, NOW(), 'cancellation') + ON CONFLICT (idempotency_key) DO NOTHING + `, r.ID, *r.BookingID, float64(r.AmountPence)/100.0, + "Stranded charge on cancelled booking "+status+" — auto-refunded by stale-pending sweep", + r.ID+"-square-"+strconv.FormatInt(r.AmountPence, 10), r.CreatedBy); rfErr != nil { + log.Printf("CRITICAL: stale pending payment %s (booking %s) is COMPLETED but creating its auto-refund row errored (%v) — MANUAL RECONCILIATION REQUIRED: refund the charge manually", r.ID, *r.BookingID, rfErr) + } + } if cErr := tx.Commit(ctx); cErr != nil { log.Printf("CRITICAL: Square payment for stale pending row %s is COMPLETED but booking %s is %q — committing the failed mark errored (%v) — MANUAL RECONCILIATION REQUIRED", r.ID, *r.BookingID, status, cErr) return staleBookingGateUnknown } if int(tag.RowsAffected()) > 0 { insertCriticalPaymentNotification(ctx, r.BookingID, r.CreatedBy) - log.Printf("CRITICAL: stale pending payment %s is COMPLETED at Square but booking %s is %q — payment marked FAILED instead of completed; operator must refund the customer manually", r.ID, *r.BookingID, status) + log.Printf("CRITICAL: stale pending payment %s is COMPLETED at Square but booking %s is %q — payment marked FAILED instead of completed; an automatic refund row was created for the stranded charge — verify the Square refund settles", r.ID, *r.BookingID, status) return staleBookingGateRefused } // The row was already resolved concurrently — nothing left to refuse. @@ -898,6 +947,25 @@ func insertOutstandingGiftCardFundingTrace(ctx context.Context, r staleRow) { // instant (replayAt), is ambiguous / a provable expired-key duplicate. const replayRescueLowerBoundSkew = 5 * time.Minute +// replayRescueUpperBoundSkew is the tolerance applied to the UPPER bound of +// the legitimate window (replayWithinLegitimateWindow): a replayed COMPLETED +// payment created this far AFTER the sweep's own replay instant (replayAt) is +// still treated as the ORIGINAL charge / a legit same-key retry rather than a +// provably-new expired-key duplicate. The strict bound (created.Before(replayAt)) +// had no clock-skew tolerance: Square's clock can run a few seconds AHEAD of +// the app's, so a legitimately-authorized same-key retry that raced the sweep +// (the retry charge lands at Square a moment before the sweep's replay while +// Square's clock already reads past replayAt) would be misclassified as the +// sweep's OWN replay-created duplicate and AUTO-REFUNDED — reversing a charge +// the customer authorized. The 5s window absorbs that skew. The trade-off — +// the sweep's own replay-created charge could be created within 5s of replayAt +// by the same skew and be rescued rather than auto-refunded — is bounded and +// acceptable: such a charge is created BY the very replay whose result this +// discriminates, and the B1 in-flight guard + b1_attempts cap + refund re-poll +// continue to bound any residual duplicate; the wrongly-refunded-legit-retry +// direction this tolerance removes is unbounded by anything. +const replayRescueUpperBoundSkew = 5 * time.Second + // replayMatchesRowAmount reports whether the replayed payment charged the same // amount the pending row records — the amount the sweep's replay body repeats // and the amount any same-key retry MUST reuse (the retry path rejects a @@ -944,8 +1012,11 @@ func replayWithinLegitimateWindow(r staleRow, replayAt time.Time, pr *square.Pay // before the replay is the original or a legit retry; created at/after the // replay is the sweep's own creation (expired-key duplicate). Comparing // against replayAt instead of a fixed row-age window makes the decision - // independent of Square's unverified ~24h key-retention window. - return created.Before(replayAt) + // independent of Square's unverified ~24h key-retention window. The small + // replayRescueUpperBoundSkew tolerance keeps a legit same-key retry that + // raced the sweep from being misread as the sweep's own replay-created + // charge when Square's clock runs a few seconds ahead of the app's (MINOR). + return created.Before(replayAt.Add(replayRescueUpperBoundSkew)) } // isSavedCardSource reports whether a Square source id is a card-on-file @@ -1603,21 +1674,63 @@ func leaveGiftCardPurchasePending(ctx context.Context, r staleRow) { // different call paths (sweep vs webhook) — do not merge them, and if the // NOT EXISTS guard shape ever changes, update BOTH copies. func insertCriticalPaymentNotification(ctx context.Context, bookingID, userID *string) { - tag, err := db.Conn.Exec(ctx, ` + // Apply the SAME global flood cap as every other 'critical_payment_log' + // insert site (webhooks, account erasure, jwt reuse, time-blockers, cleanup): + // a fast-path suppression pre-check, then the cap folded INTO the INSERT. + // + // The count-then-insert critical section is serialized on a transaction- + // scoped advisory lock so it is TRULY atomic (F6): under READ COMMITTED, N + // concurrent inserts can each evaluate the COUNT subquery against a snapshot + // taken before ANY of them commits, so all N pass the `< $cap` check and the + // cap is overshot by N. pg_advisory_xact_lock makes each waiter's COUNT run + // only AFTER the previous insert committed, so the unacknowledged queue + // never exceeds the cap — the overshoot is bounded by exactly zero instead + // of by the concurrency. The transaction is one short INSERT, so the + // blocking xact lock (no 3s bound — see acquireAdvisoryXactLockBlocking) + // is fine here. + // + // The per-issue NOT EXISTS dedup is preserved, so each issue still gets + // exactly one notification. + if adminnotify.CriticalLogsCapExceeded(ctx, db.Conn, "critical_payment_log") { + slog.Warn("suppressed critical-payment admin notification — unacknowledged 'critical_payment_log' queue at the cap", "booking", bookingID, "user", userID) + return + } + tx, err := db.Conn.Begin(ctx) + if err != nil { + log.Printf("Failed to begin critical-payment admin notification insert: %v", err) + return + } + defer func() { + if err := tx.Rollback(ctx); err != nil && !errors.Is(err, pgx.ErrTxClosed) { + log.Printf("Failed to rollback critical-payment admin notification insert: %v", err) + } + }() + if err := acquireAdvisoryXactLockBlocking(ctx, tx, "crussell:critical-payment-log-cap"); err != nil { + log.Printf("Failed to acquire critical-payment admin notification cap lock: %v", err) + return + } + tag, err := tx.Exec(ctx, ` INSERT INTO admin_notifications (reason, booking_id, user_id, created_at) SELECT 'critical_payment_log', $1, $2, NOW() - WHERE NOT EXISTS ( + WHERE (SELECT COUNT(*) FROM admin_notifications _an + WHERE _an.reason = 'critical_payment_log' + AND _an.acknowledged_at IS NULL) < $3 + AND NOT EXISTS ( SELECT 1 FROM admin_notifications an WHERE an.reason = 'critical_payment_log' AND an.booking_id IS NOT DISTINCT FROM $1 AND an.user_id IS NOT DISTINCT FROM $2 AND an.acknowledged_at IS NULL ) - `, bookingID, userID) + `, bookingID, userID, adminnotify.MaxUnacknowledgedCriticalLogs) if err != nil { log.Printf("Failed to insert admin_notifications for critical payment issue (booking=%v user=%v): %v", bookingID, userID, err) return } + if err := tx.Commit(ctx); err != nil { + log.Printf("Failed to commit critical-payment admin notification insert: %v", err) + return + } if int(tag.RowsAffected()) > 0 { log.Printf("Inserted critical-payment admin notification (booking=%v user=%v)", bookingID, userID) } @@ -2004,20 +2117,45 @@ func SweepStaleTerminalCheckouts(ctx context.Context) (int, error) { } log.Printf("Cancelled stale terminal checkout %s (%s %s, pending >%s) but re-check shows COMPLETED — payment recorded by the sweep", r.CheckoutID, r.Kind, r.RowID, staleTerminalCheckoutAge) case isTerminalCheckoutError(rErr) || errors.Is(rErr, square.ErrCheckoutPending): - // The cancel landed (CANCELED / cancel-requested / expired / - // still-reporting-pending-but-now-cancelled) — it can never - // complete, so resolve the row to the terminal 'failed' state. - // A till sale's funded gift card is clawed back (a cancel that - // landed cannot later complete); a booking terminal_checkout - // has no gift card. - if r.Kind == "till_sale" { + // The re-check after the cancel came back terminal-or-still-live + // (CANCELED / NOT_FOUND / CANCEL_REQUESTED / PENDING). C3: the + // clawback is gated on isCheckoutDefinitivelyDead exactly like + // the first-check branch below — only an explicit CANCELED / + // NOT_FOUND PROVES the charge can never complete. A checkout + // still reporting live or cancel-requested at the re-check can + // STILL complete at the terminal (the card payment raced the + // cancel / Square's cancel propagation lagged), and clawing back + // the funding on a charge that later lands would take the + // customer's card money AND the gift-card value (silent + // money-taken). + switch { + case r.Kind == "till_sale" && isCheckoutDefinitivelyDead(rErr): + // Provably dead — the funding has no charge behind it. if clawBackTillSaleFunding(ctx, r.RowID) { resolved++ } - } else if markTerminalCheckoutRowFailed(ctx, r) { - resolved++ + log.Printf("Cancelled stale terminal checkout %s (till sale %s, pending >%s) — re-check proves the charge can never complete; marked failed with gift-card funding clawed back", r.CheckoutID, r.RowID, staleTerminalCheckoutAge) + case !isCheckoutDefinitivelyDead(rErr): + // The cancel did NOT provably take effect — the re-check + // reports the checkout still live (PENDING / IN_PROGRESS / + // CANCEL_REQUESTED). Marking the row failed now would DROP + // the live checkout: a charge that completes at the terminal + // LATER would land with no payments row and no alert — a + // permanently untracked charge (money-F3). Keep the row in + // flight for manual reconciliation (an operator verifies the + // checkout state at Square), raise the CRITICAL admin + // notification, and surface a till sale's outstanding + // gift-card funding as an 'awaiting_reversal' trace row. + leaveTerminalCheckoutReconciliationRequired(ctx, r) + log.Printf("CRITICAL: stale terminal checkout %s (%s %s, pending >%s) was cancelled but the re-check is still live / not provably dead (%v) — NOT marked failed; left pending for manual reconciliation — verify the checkout state at Square whether the charge completed — MANUAL RECONCILIATION REQUIRED", r.CheckoutID, r.Kind, r.RowID, staleTerminalCheckoutAge, rErr) + default: + // Definitively terminal (CANCELED / NOT_FOUND) and no + // gift-card funding to protect — safe to fail. + if markTerminalCheckoutRowFailed(ctx, r) { + resolved++ + } + log.Printf("Cancelled stale terminal checkout %s (%s %s, pending >%s) — marked failed", r.CheckoutID, r.Kind, r.RowID, staleTerminalCheckoutAge) } - log.Printf("Cancelled stale terminal checkout %s (%s %s, pending >%s) — marked failed", r.CheckoutID, r.Kind, r.RowID, staleTerminalCheckoutAge) default: // The cancel succeeded but the re-check itself is ambiguous — // leave the row for a later run. @@ -2084,6 +2222,53 @@ type staleTerminalCheckoutRow struct { BookingID string } +// leaveTerminalCheckoutReconciliationRequired keeps a stale terminal checkout +// row in flight (PENDING / IN_PROGRESS) after the sweep could NOT PROVABLY +// cancel it at Square — the cancel-then-recheck still reports the checkout live +// or only cancel-requested. Marking the row failed would DROP the live checkout: +// a charge that later completes at the terminal would land with no payments row +// and no admin alert — permanently untracked (money-F3). Instead the row stays +// pending for manual reconciliation (an operator verifies the checkout state at +// Square), the CRITICAL admin notification is raised (flood-capped, deduped per +// booking/user), and a till sale's outstanding gift-card funding is surfaced as +// an 'awaiting_reversal' trace row — the same manual-resolution path +// insertOutstandingGiftCardFundingTrace drives — so the operator can see the +// funding while reconciling. The row is deliberately NOT counted as resolved. +func leaveTerminalCheckoutReconciliationRequired(ctx context.Context, r staleTerminalCheckoutRow) { + var bookingID *string + var userID *string + if r.Kind == "terminal_checkout" && r.BookingID != "" { + bookingID = &r.BookingID + } + if r.Kind == "till_sale" { + // Attribute the alert to the funded gift card's redeemed-to user when + // there is one and surface the outstanding funding as a trace row. + var itemType string + var itemID sql.NullString + var totalAmount float64 + var redeemedBy sql.NullString + if err := db.Conn.QueryRow(ctx, ` + SELECT ts.item_type, ts.item_id, ts.total_amount, gc.redeemed_by + FROM till_sales ts + LEFT JOIN gift_cards gc ON gc.id = ts.item_id + WHERE ts.id = $1 + `, r.RowID).Scan(&itemType, &itemID, &totalAmount, &redeemedBy); err != nil { + log.Printf("CRITICAL: failed to look up till sale %s for outstanding-funding trace: %v — MANUAL RECONCILIATION REQUIRED", r.RowID, err) + } else if itemType == "gift_card" && itemID.Valid && itemID.String != "" { + if redeemedBy.Valid && redeemedBy.String != "" { + userID = &redeemedBy.String + } + if _, tErr := db.Conn.Exec(ctx, ` + INSERT INTO gift_card_transactions (gift_card_id, transaction_type, amount, reference_type, reference_id, user_id, notes) + VALUES ($1, 'awaiting_reversal', $2, 'till_sale', $3, $4, $5) + `, itemID.String, totalAmount, r.RowID, userID, "cancel-recheck still live: checkout not provably cancelled at Square — verify its state there manually before resolving"); tErr != nil { + log.Printf("Failed to insert outstanding gift-card funding trace for till sale %s: %v", r.RowID, tErr) + } + } + } + insertCriticalPaymentNotification(ctx, bookingID, userID) +} + // markTerminalCheckoutRowFailed moves one tracked row to the terminal 'failed' // state after its checkout is cancelled or proven terminal at Square. Returns // true when the row was updated (status was still active). diff --git a/backend/handlers/payments/sweep_boundary_test.go b/backend/handlers/payments/sweep_boundary_test.go new file mode 100644 index 0000000..aa95b43 --- /dev/null +++ b/backend/handlers/payments/sweep_boundary_test.go @@ -0,0 +1,334 @@ +//go:build test && dev + +package payments + +// M14 sweep boundary tests. The three sweeps select rows with a strict +// `created_at < cutoff` comparison against cutoffs computed from clock.Now() +// (the single wall-clock source — the M3 contract). These tests pin the +// boundary behaviour with rows aged just INSIDE the window (left pending / +// untouched) and just OUTSIDE it (swept), for every cutoff the earlier +// reviews left without an explicit epsilon boundary test: +// +// - stalePendingKeyedAge (22h) — the keyed lost-response pass; +// - staleTerminalCheckoutAge (1h) — the terminal checkout sweep; +// - stalePendingRefundAge (23h) — the pending Square refund sweep. +// +// The 24h stalePendingPaymentAge boundary is already locked by +// TestSweepStalePendingPayments_AgeBoundary_23h_24h in sweep_test.go. All +// margin epsilons are comfortably above any Go-clock/DB-clock skew on the test +// host so the strict < comparison can never flip on clock drift. These tests +// are sequential (no t.Parallel): they swap the package-global SquareClient +// and mutate the shared test pool, exactly like the other sweep tests. + +import ( + "context" + "testing" + "time" + + "crussell/db" + "crussell/internal/square" + "crussell/testutils" + "crussell/testutils/fixtures" +) + +// TestSweepStalePendingPayments_KeyedCutoffBoundary locks the 22h keyed-pass +// boundary: a keyed pending row aged just INSIDE stalePendingKeyedAge (22h) +// is NOT stale for the keyed pass AND not yet past the 24h stale-pending +// cutoff, so it stays pending; a row aged just OUTSIDE the 22h cutoff (but +// still inside Square's ~24h retention window) is picked up by the keyed +// pass, replayed, and — with a spent cnon source and no payment under the key +// at Square — definitively failed. +func TestSweepStalePendingPayments_KeyedCutoffBoundary(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + userID, err := fixtures.CreateTestUser(tx) + if err != nil { + t.Fatalf("failed to create user: %v", err) + } + serviceID, err := fixtures.CreateTestService(tx) + if err != nil { + t.Fatalf("failed to create service: %v", err) + } + bookingID, err := fixtures.CreateTestBookingAtTime(tx, userID, serviceID, + time.Date(2099, 12, 31, 10, 0, 0, 0, time.UTC)) + if err != nil { + t.Fatalf("failed to create booking: %v", err) + } + + // INSIDE the 22h keyed cutoff: 21h55m old → created_at >= keyedCutoff → + // the keyed pass must NOT fetch it, and it is under the 24h stale cutoff + // too → stays pending. + insideID, err := fixtures.CreateTestPayment(tx, bookingID, 2000.00, "online_square", "full", "pending") + if err != nil { + t.Fatalf("failed to create inside payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET created_at = NOW() - INTERVAL '21 hours 55 minutes', idempotency_key = 'key-boundary-inside', square_source_id = 'cnon:test-card' WHERE id = $1", insideID); err != nil { + t.Fatalf("failed to age the inside payment: %v", err) + } + + // OUTSIDE the 22h keyed cutoff: 22h05m old → past the keyed cutoff, still + // inside Square's ~24h retention window → the keyed pass replays and fails + // it (spent cnon, no payment under the key). + outsideID, err := fixtures.CreateTestPayment(tx, bookingID, 2000.00, "online_square", "full", "pending") + if err != nil { + t.Fatalf("failed to create outside payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET created_at = NOW() - INTERVAL '22 hours 5 minutes', idempotency_key = 'key-boundary-outside', square_source_id = 'cnon:test-card' WHERE id = $1", outsideID); err != nil { + t.Fatalf("failed to age the outside payment: %v", err) + } + + origClient := SquareClient + // A fresh mock has no payment under either key → ReplayPaymentByKey + // returns ErrReplayKeyNotRetained; with a spent-cnon source that is + // definitive proof of no charge → the outside row is failed. + SquareClient = square.NewDevClient() + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit test tx: %v", err) + } + + pool := context.Background() + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM payments WHERE id = ANY($1)`, []string{insideID, outsideID}) + _, _ = db.Conn.Exec(pool, `DELETE FROM bookings WHERE id = $1`, bookingID) + _, _ = db.Conn.Exec(pool, `DELETE FROM services WHERE id = $1`, serviceID) + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, userID) + }) + + if _, err := SweepStalePendingPayments(pool); err != nil { + t.Fatalf("sweep failed: %v", err) + } + + // Just INSIDE the 22h keyed cutoff: not stale → stays pending. + var insideStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM payments WHERE id = $1", insideID).Scan(&insideStatus); err != nil { + t.Fatalf("failed to query inside payment: %v", err) + } + if insideStatus != "pending" { + t.Errorf("expected a keyed row 21h55m old (inside the 22h cutoff) to stay pending, got %q", insideStatus) + } + + // Just OUTSIDE the 22h keyed cutoff: the keyed pass swept it to failed. + var outsideStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM payments WHERE id = $1", outsideID).Scan(&outsideStatus); err != nil { + t.Fatalf("failed to query outside payment: %v", err) + } + if outsideStatus != "failed" { + t.Errorf("expected a keyed row 22h05m old (outside the 22h cutoff) swept to failed, got %q", outsideStatus) + } +} + +// TestSweepStaleTerminalCheckouts_AgeCutoffBoundary locks the 1h terminal +// sweep boundary: a PENDING terminal checkout aged just INSIDE +// staleTerminalCheckoutAge stays live (the sweep must not touch it), while a +// checkout aged just OUTSIDE it is cancelled and its terminal_checkouts row +// marked failed. +func TestSweepStaleTerminalCheckouts_AgeCutoffBoundary(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + userID, bookingID, serviceID := setupTestData(t, ctx, tx) + + origClient := SquareClient + mock := square.NewDevClient().(*square.MockClient) + mock.HoldCheckouts = true + inside, err := mock.CreateCheckout(context.Background(), square.CreateCheckoutReq{ + Amount: 5000, + Currency: "GBP", + IdempotencyKey: "chk-boundary-inside", + }) + if err != nil { + t.Fatalf("failed to create inside checkout: %v", err) + } + outside, err := mock.CreateCheckout(context.Background(), square.CreateCheckoutReq{ + Amount: 5000, + Currency: "GBP", + IdempotencyKey: "chk-boundary-outside", + }) + if err != nil { + t.Fatalf("failed to create outside checkout: %v", err) + } + SquareClient = mock + defer func() { SquareClient = origClient }() + + // INSIDE: 59m old → not past the 1h cutoff → must be left alone. + if _, err := tx.Exec(ctx, ` + INSERT INTO terminal_checkouts (checkout_id, booking_id, payment_type, status, amount, created_at) + VALUES ($1, $2, 'full', 'PENDING', 50.00, NOW() - INTERVAL '59 minutes') + `, inside.ID, bookingID); err != nil { + t.Fatalf("failed to seed inside terminal checkout: %v", err) + } + // OUTSIDE: 61m old → past the 1h cutoff → cancelled + marked failed. + if _, err := tx.Exec(ctx, ` + INSERT INTO terminal_checkouts (checkout_id, booking_id, payment_type, status, amount, created_at) + VALUES ($1, $2, 'full', 'PENDING', 50.00, NOW() - INTERVAL '61 minutes') + `, outside.ID, bookingID); err != nil { + t.Fatalf("failed to seed outside terminal checkout: %v", err) + } + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit test tx: %v", err) + } + + pool := context.Background() + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM terminal_checkouts WHERE checkout_id IN ($1, $2)`, inside.ID, outside.ID) + _, _ = db.Conn.Exec(pool, `DELETE FROM bookings WHERE id = $1`, bookingID) + _, _ = db.Conn.Exec(pool, `DELETE FROM services WHERE id = $1`, serviceID) + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, userID) + }) + // Drop any other stale terminal rows left by parallel tests so the count + // is deterministic. + if _, err := db.Conn.Exec(pool, `DELETE FROM terminal_checkouts WHERE status IN ('PENDING', 'IN_PROGRESS') AND checkout_id NOT IN ($1, $2)`, inside.ID, outside.ID); err != nil { + t.Fatalf("failed to clean leftover stale terminal checkouts: %v", err) + } + if _, err := db.Conn.Exec(pool, `DELETE FROM till_sales WHERE status = 'pending' AND square_checkout_id IS NOT NULL`); err != nil { + t.Fatalf("failed to clean leftover stale till sales: %v", err) + } + + n, err := SweepStaleTerminalCheckouts(pool) + if err != nil { + t.Fatalf("sweep failed: %v", err) + } + if n != 1 { + t.Errorf("expected exactly 1 resolved terminal checkout (only the 61m-old one), got %d", n) + } + + var insideStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM terminal_checkouts WHERE checkout_id = $1", inside.ID).Scan(&insideStatus); err != nil { + t.Fatalf("failed to query inside checkout: %v", err) + } + if insideStatus != "PENDING" { + t.Errorf("expected a 59m-old checkout (inside the 1h cutoff) left PENDING, got %q", insideStatus) + } + + var outsideStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM terminal_checkouts WHERE checkout_id = $1", outside.ID).Scan(&outsideStatus); err != nil { + t.Fatalf("failed to query outside checkout: %v", err) + } + if outsideStatus != "failed" { + t.Errorf("expected a 61m-old checkout (outside the 1h cutoff) marked failed, got %q", outsideStatus) + } +} + +// TestSweepPendingSquareRefunds_AgeGuardBoundary locks the 23h refund-sweep +// boundary: a pending cancellation refund aged just INSIDE stalePendingRefundAge +// is re-issued at Square (money still provably unmoved under a retained key), +// while a refund aged just OUTSIDE it is reconciled first — and with no +// COMPLETED refund at Square, marked failed + admin-notified (never re-issued +// into a double-refund). +func TestSweepPendingSquareRefunds_AgeGuardBoundary(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + userID, err := fixtures.CreateTestUser(tx) + if err != nil { + t.Fatalf("failed to create user: %v", err) + } + serviceID, err := fixtures.CreateTestService(tx) + if err != nil { + t.Fatalf("failed to create service: %v", err) + } + insideBooking, err := fixtures.CreateTestBookingAtTime(tx, userID, serviceID, + time.Date(2099, 12, 31, 10, 0, 0, 0, time.UTC)) + if err != nil { + t.Fatalf("failed to create inside booking: %v", err) + } + outsideBooking, err := fixtures.CreateTestBookingAtTime(tx, userID, serviceID, + time.Date(2099, 12, 31, 10, 0, 0, 0, time.UTC)) + if err != nil { + t.Fatalf("failed to create outside booking: %v", err) + } + + // Two completed online payments with Square charge ids — one per refund. + insidePay, err := fixtures.CreateTestPayment(tx, insideBooking, 25.00, "online_square", "deposit", "completed") + if err != nil { + t.Fatalf("failed to create inside payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET square_payment_id = 'sqp_refund_boundary_inside' WHERE id = $1", insidePay); err != nil { + t.Fatalf("failed to set inside square_payment_id: %v", err) + } + outsidePay, err := fixtures.CreateTestPayment(tx, outsideBooking, 25.00, "online_square", "deposit", "completed") + if err != nil { + t.Fatalf("failed to create outside payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET square_payment_id = 'sqp_refund_boundary_outside' WHERE id = $1", outsidePay); err != nil { + t.Fatalf("failed to set outside square_payment_id: %v", err) + } + + // INSIDE: 22h55m old → not yet past the 23h guard → the sweep issues the + // Square refund (money provably unmoved under a retained key). + var insideRefundID string + if err := tx.QueryRow(ctx, ` + INSERT INTO refunds (payment_id, booking_id, amount, status, reason, idempotency_key, origin, created_at) + VALUES ($1, $2, 25, 'pending', 'client_cancelled', $3, 'cancellation', NOW() - INTERVAL '22 hours 55 minutes') + RETURNING id + `, insidePay, insideBooking, insidePay+"-square-2500").Scan(&insideRefundID); err != nil { + t.Fatalf("failed to insert inside refund: %v", err) + } + + // OUTSIDE: 23h05m old → past the 23h guard → reconciled first; no + // COMPLETED refund at Square → marked failed. + var outsideRefundID string + if err := tx.QueryRow(ctx, ` + INSERT INTO refunds (payment_id, booking_id, amount, status, reason, idempotency_key, origin, created_at) + VALUES ($1, $2, 25, 'pending', 'client_cancelled', $3, 'cancellation', NOW() - INTERVAL '23 hours 5 minutes') + RETURNING id + `, outsidePay, outsideBooking, outsidePay+"-square-2500").Scan(&outsideRefundID); err != nil { + t.Fatalf("failed to insert outside refund: %v", err) + } + + origClient := SquareClient + SquareClient = square.NewDevClient() + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit test tx: %v", err) + } + + pool := context.Background() + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM refunds WHERE id IN ($1, $2)`, insideRefundID, outsideRefundID) + _, _ = db.Conn.Exec(pool, `DELETE FROM payments WHERE id IN ($1, $2)`, insidePay, outsidePay) + _, _ = db.Conn.Exec(pool, `DELETE FROM bookings WHERE id IN ($1, $2)`, insideBooking, outsideBooking) + _, _ = db.Conn.Exec(pool, `DELETE FROM services WHERE id = $1`, serviceID) + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, userID) + }) + + if _, err := SweepPendingSquareRefunds(pool); err != nil { + t.Fatalf("refund sweep failed: %v", err) + } + + // INSIDE the 23h guard: the refund is re-issued and completed at Square. + var insideStatus string + var insideSqRefundID *string + if err := db.Conn.QueryRow(pool, "SELECT status, square_refund_id FROM refunds WHERE id = $1", insideRefundID).Scan(&insideStatus, &insideSqRefundID); err != nil { + t.Fatalf("failed to query inside refund: %v", err) + } + if insideStatus != "completed" { + t.Errorf("expected a refund 22h55m old (inside the 23h guard) re-issued to 'completed', got %q", insideStatus) + } + if insideSqRefundID == nil || *insideSqRefundID == "" { + t.Error("expected the inside refund to carry a square_refund_id (Square was called)") + } + + // OUTSIDE the 23h guard: reconciled, no COMPLETED refund → failed. + var outsideStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM refunds WHERE id = $1", outsideRefundID).Scan(&outsideStatus); err != nil { + t.Fatalf("failed to query outside refund: %v", err) + } + if outsideStatus != "failed" { + t.Errorf("expected a refund 23h05m old (outside the 23h guard) reconciled to 'failed', got %q", outsideStatus) + } +} diff --git a/backend/handlers/payments/sweep_test.go b/backend/handlers/payments/sweep_test.go index 3516a55..2126142 100644 --- a/backend/handlers/payments/sweep_test.go +++ b/backend/handlers/payments/sweep_test.go @@ -5,12 +5,15 @@ package payments import ( "bytes" "context" + "database/sql" "errors" "fmt" + "sync" "testing" "time" "crussell/db" + "crussell/internal/adminnotify" "crussell/internal/square" "crussell/testutils" "crussell/testutils/fixtures" @@ -3164,18 +3167,22 @@ func TestSweepStaleTerminalCheckouts_MockNotFound_Clawbacks(t *testing.T) { } } -// TestSweepStaleTerminalCheckouts_MockCancelRequested_CancelThenClawback +// TestSweepStaleTerminalCheckouts_MockCancelRequested_CancelThenNoClawback // exercises the cancel-then-recheck path for a CANCEL_REQUESTED checkout via // the dev mock: GetCheckout folds CANCEL_REQUESTED into ErrCheckoutPending // (mirroring the real client, which treats it as still-live), the sweep calls // CancelCheckout (a no-op — Square returns 404 for an already-canceling -// checkout), and the re-check — still ErrCheckoutPending — resolves the sale -// to failed with the funding clawed back. The separate -// CANCEL_REQUESTED-only "not provably dead, no clawback" classification of -// isCheckoutDefinitivelyDead is locked by -// TestSweepStaleTerminalCheckouts_TillCancelRequested_NoClawback, which -// injects a non-pending CANCEL_REQUESTED error the real client never emits. -func TestSweepStaleTerminalCheckouts_MockCancelRequested_CancelThenClawback(t *testing.T) { +// checkout), and the re-check — still ErrCheckoutPending — is NOT provably +// dead. money-F3: because the cancel did NOT provably take effect (the charge +// may still complete at Square after the cancel), the sale is NOT marked +// failed — it is left PENDING for manual reconciliation, a CRITICAL admin +// notification is raised, and the funded gift card is NOT clawed back. The +// separate CANCEL_REQUESTED-only "not provably dead, no clawback" FIRST-check +// classification of isCheckoutDefinitivelyDead is locked by +// TestSweepStaleTerminalCheckouts_TillCancelRequested_NoClawback, and the +// definitively-dead cancel-recheck path (re-check proves CANCELED) is locked +// by TestSweepStaleTerminalCheckouts_CancelsStalePending. +func TestSweepStaleTerminalCheckouts_MockCancelRequested_CancelThenNoClawback(t *testing.T) { ctx, tx := testutils.SetupTestTx(t) adminID, err := fixtures.CreateTestAdminUser(tx) @@ -3228,30 +3235,264 @@ func TestSweepStaleTerminalCheckouts_MockCancelRequested_CancelThenClawback(t *t t.Fatalf("failed to clean leftover stale booking terminal checkouts: %v", err) } + if _, err := db.Conn.Exec(pool, `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id IS NULL AND user_id IS NULL`); err != nil { + t.Fatalf("failed to clean leftover critical notifications: %v", err) + } + if _, err := db.Conn.Exec(pool, `DELETE FROM gift_card_transactions WHERE gift_card_id = $1 AND transaction_type = 'awaiting_reversal'`, giftCardID); err != nil { + t.Fatalf("failed to clean leftover reconciliation traces: %v", err) + } + n, err := SweepStaleTerminalCheckouts(pool) if err != nil { t.Fatalf("sweep failed: %v", err) } - if n != 1 { - t.Errorf("expected exactly 1 resolved stale terminal checkout, got %d", n) + if n != 0 { + t.Errorf("expected a cancel-recheck that is still live / not provably dead to be left UNRESOLVED for reconciliation, got %d resolutions", n) } var status string if err := db.Conn.QueryRow(pool, `SELECT status FROM till_sales WHERE id = $1`, saleID).Scan(&status); err != nil { t.Fatalf("failed to query till sale: %v", err) } - if status != "failed" { - t.Errorf("expected CANCEL_REQUESTED (cancel-recheck) till sale marked failed, got %q", status) + if status != "pending" { + t.Errorf("expected a not-provably-dead cancel-recheck till sale left 'pending' (money-F3: never marked failed), got %q", status) } - // The sweep believed the cancel landed, so the created gift card is clawed - // back (deleted) — the same path the real Square API produces. + // C3 / money-F3: the re-check is still live / cancel-requested, so the + // charge may still complete at Square — the funded gift card must NOT be + // clawed back (the pre-fix code deleted it, taking the customer's money AND + // the card value if the charge later landed). var cardCount int - if err := db.Conn.QueryRow(pool, `SELECT COUNT(*) FROM gift_cards WHERE id = $1`, giftCardID).Scan(&cardCount); err != nil { - t.Fatalf("failed to count gift cards: %v", err) + var remaining float64 + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*), COALESCE(MAX(amount_remaining), 0) FROM gift_cards WHERE id = $1`, giftCardID).Scan(&cardCount, &remaining); err != nil { + t.Fatalf("failed to query gift card: %v", err) } - if cardCount != 0 { - t.Errorf("expected the clawed-back created gift card deleted, got %d cards", cardCount) + if cardCount != 1 || remaining != 50.00 { + t.Errorf("expected the funded gift card KEPT after a not-provably-dead cancel-recheck, got count=%d remaining=%.2f", cardCount, remaining) + } + + // money-F3: a CRITICAL admin notification must be raised so an operator + // verifies the Square checkout state manually. + var notifCount int + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*) FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id IS NULL AND user_id IS NULL`).Scan(¬ifCount); err != nil { + t.Fatalf("failed to count critical notifications: %v", err) + } + if notifCount != 1 { + t.Errorf("expected exactly 1 CRITICAL admin notification for the still-live cancel-recheck, got %d", notifCount) + } + + // money-F3: the outstanding gift-card funding must be surfaced as an + // 'awaiting_reversal' trace row for the operator's manual resolution. + var traceCount int + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*) FROM gift_card_transactions WHERE gift_card_id = $1 AND transaction_type = 'awaiting_reversal' AND reference_id = $2`, giftCardID, saleID).Scan(&traceCount); err != nil { + t.Fatalf("failed to count reconciliation traces: %v", err) + } + if traceCount != 1 { + t.Errorf("expected exactly 1 outstanding-funding trace row for the still-live cancel-recheck, got %d", traceCount) + } +} + +// stillLiveAfterCancelClient reports ErrCheckoutPending on EVERY GetCheckout for +// the target checkout — the cancel did not provably take effect at Square (the +// cancel request was accepted but the checkout stays live; a customer could +// still complete the payment on the terminal). Everything else delegates to the +// underlying mock. +type stillLiveAfterCancelClient struct { + square.SquareClient + checkoutID string + calls int +} + +func (c *stillLiveAfterCancelClient) GetCheckout(ctx context.Context, checkoutID string) (*square.PaymentResult, error) { + if checkoutID == c.checkoutID { + c.calls++ + return nil, square.ErrCheckoutPending + } + return c.SquareClient.GetCheckout(ctx, checkoutID) +} + +// TestSweepStaleTerminalCheckouts_StillLiveAfterCancel_TillSale locks the +// money-F3 fix for a TILL-SALE checkout whose cancel did not provably take +// effect: the sweep cancels the stale checkout but the re-check STILL reports +// it live (ErrCheckoutPending), so the card charge can still complete at +// Square. The sale must NOT be marked failed (a failed mark would drop the live +// checkout — a late completion becomes a permanently untracked charge with no +// alert); instead the sale stays PENDING for manual reconciliation, a CRITICAL +// admin notification is raised, and the outstanding gift-card funding is +// surfaced as an 'awaiting_reversal' trace row. The funded gift card is not +// clawed back. +func TestSweepStaleTerminalCheckouts_StillLiveAfterCancel_TillSale(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + adminID, err := fixtures.CreateTestAdminUser(tx) + if err != nil { + t.Fatalf("failed to create admin user: %v", err) + } + pool := context.Background() + + const checkoutID = "chk_still_live_after_cancel_till" + saleID, giftCardID := seedStaleTerminalTillSale(t, ctx, tx, adminID, true) + if _, err := tx.Exec(ctx, `UPDATE till_sales SET square_checkout_id = $1 WHERE id = $2`, checkoutID, saleID); err != nil { + t.Fatalf("failed to set checkout id: %v", err) + } + if _, err := tx.Exec(ctx, ` + INSERT INTO gift_card_transactions (gift_card_id, transaction_type, amount, reference_type, reference_id) + VALUES ($1, 'purchase', 50.00, 'till_sale', $2) + `, giftCardID, saleID); err != nil { + t.Fatalf("failed to seed gift card transaction: %v", err) + } + + origClient := SquareClient + SquareClient = &stillLiveAfterCancelClient{SquareClient: square.NewDevClient(), checkoutID: checkoutID} + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit setup tx: %v", err) + } + + if _, err := db.Conn.Exec(pool, `DELETE FROM till_sales WHERE status = 'pending' AND square_checkout_id IS NOT NULL AND id <> $1`, saleID); err != nil { + t.Fatalf("failed to clean leftover stale terminal sales: %v", err) + } + if _, err := db.Conn.Exec(pool, `DELETE FROM terminal_checkouts WHERE status IN ('PENDING', 'IN_PROGRESS')`); err != nil { + t.Fatalf("failed to clean leftover stale booking terminal checkouts: %v", err) + } + if _, err := db.Conn.Exec(pool, `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id IS NULL AND user_id IS NULL`); err != nil { + t.Fatalf("failed to clean leftover critical notifications: %v", err) + } + if _, err := db.Conn.Exec(pool, `DELETE FROM gift_card_transactions WHERE gift_card_id = $1 AND transaction_type = 'awaiting_reversal'`, giftCardID); err != nil { + t.Fatalf("failed to clean leftover reconciliation traces: %v", err) + } + + n, err := SweepStaleTerminalCheckouts(pool) + if err != nil { + t.Fatalf("sweep failed: %v", err) + } + if n != 0 { + t.Errorf("expected a still-live-after-cancel till sale left UNRESOLVED for reconciliation, got %d resolutions", n) + } + + // NOT marked failed — the sale stays pending so the live checkout is never + // dropped from tracking. + var status string + if err := db.Conn.QueryRow(pool, `SELECT status FROM till_sales WHERE id = $1`, saleID).Scan(&status); err != nil { + t.Fatalf("failed to query till sale: %v", err) + } + if status != "pending" { + t.Errorf("expected a still-live-after-cancel till sale left 'pending' (never marked failed), got %q", status) + } + + // The funded gift card must NOT be clawed back. + var cardCount int + var remaining float64 + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*), COALESCE(MAX(amount_remaining), 0) FROM gift_cards WHERE id = $1`, giftCardID).Scan(&cardCount, &remaining); err != nil { + t.Fatalf("failed to query gift card: %v", err) + } + if cardCount != 1 || remaining != 50.00 { + t.Errorf("expected the funded gift card KEPT after a still-live cancel-recheck, got count=%d remaining=%.2f", cardCount, remaining) + } + + // A CRITICAL admin notification must be raised so an operator verifies the + // Square checkout state manually. + var notifCount int + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*) FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id IS NULL AND user_id IS NULL`).Scan(¬ifCount); err != nil { + t.Fatalf("failed to count critical notifications: %v", err) + } + if notifCount != 1 { + t.Errorf("expected exactly 1 CRITICAL admin notification for the still-live-after-cancel till sale, got %d", notifCount) + } + + // The outstanding gift-card funding must be surfaced as an + // 'awaiting_reversal' trace row for the operator's manual resolution. + var traceCount int + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*) FROM gift_card_transactions WHERE gift_card_id = $1 AND transaction_type = 'awaiting_reversal' AND reference_id = $2`, giftCardID, saleID).Scan(&traceCount); err != nil { + t.Fatalf("failed to count reconciliation traces: %v", err) + } + if traceCount != 1 { + t.Errorf("expected exactly 1 outstanding-funding trace row for the still-live-after-cancel till sale, got %d", traceCount) + } +} + +// TestSweepStaleTerminalCheckouts_StillLiveAfterCancel_Booking locks the +// money-F3 fix for a BOOKING terminal checkout whose cancel did not provably +// take effect: the re-check still reports the checkout live, so the terminal +// can still charge the card. The terminal_checkouts row must NOT be marked +// failed (the money-F3 bug: a failed mark drops the live checkout with no alert +// and a late completion becomes permanently untracked); instead it stays +// PENDING for manual reconciliation and a CRITICAL admin notification is raised +// against the booking. +func TestSweepStaleTerminalCheckouts_StillLiveAfterCancel_Booking(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + userID, bookingID, serviceID := setupTestData(t, ctx, tx) + + const checkoutID = "chk_still_live_after_cancel_booking" + if _, err := tx.Exec(ctx, ` + INSERT INTO terminal_checkouts (checkout_id, booking_id, payment_type, status, amount, created_at) + VALUES ($1, $2, 'full', 'PENDING', 50.00, NOW() - INTERVAL '2 hours') + `, checkoutID, bookingID); err != nil { + t.Fatalf("failed to seed stale terminal checkout row: %v", err) + } + + origClient := SquareClient + SquareClient = &stillLiveAfterCancelClient{SquareClient: square.NewDevClient(), checkoutID: checkoutID} + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit setup tx: %v", err) + } + + t.Cleanup(func() { + _, _ = db.Conn.Exec(context.Background(), `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id = $1`, bookingID) + _, _ = db.Conn.Exec(context.Background(), `DELETE FROM terminal_checkouts WHERE checkout_id = $1`, checkoutID) + _, _ = db.Conn.Exec(context.Background(), `DELETE FROM bookings WHERE id = $1`, bookingID) + _, _ = db.Conn.Exec(context.Background(), `DELETE FROM services WHERE id = $1`, serviceID) + _, _ = db.Conn.Exec(context.Background(), `DELETE FROM users WHERE id = $1`, userID) + }) + + freshCtx := context.Background() + if _, err := db.Conn.Exec(freshCtx, `DELETE FROM terminal_checkouts WHERE status IN ('PENDING', 'IN_PROGRESS') AND checkout_id <> $1`, checkoutID); err != nil { + t.Fatalf("failed to clean leftover stale terminal checkouts: %v", err) + } + if _, err := db.Conn.Exec(freshCtx, `DELETE FROM till_sales WHERE status = 'pending' AND square_checkout_id IS NOT NULL`); err != nil { + t.Fatalf("failed to clean leftover stale till sales: %v", err) + } + if _, err := db.Conn.Exec(freshCtx, `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id = $1`, bookingID); err != nil { + t.Fatalf("failed to clean leftover critical notifications: %v", err) + } + + n, err := SweepStaleTerminalCheckouts(freshCtx) + if err != nil { + t.Fatalf("sweep failed: %v", err) + } + if n != 0 { + t.Errorf("expected a still-live-after-cancel booking checkout left UNRESOLVED for reconciliation, got %d resolutions", n) + } + + // NOT marked failed — the row stays PENDING so the live checkout is never + // dropped from tracking. + var status string + if err := db.Conn.QueryRow(freshCtx, `SELECT status FROM terminal_checkouts WHERE checkout_id = $1`, checkoutID).Scan(&status); err != nil { + t.Fatalf("failed to query terminal checkout: %v", err) + } + if status != "PENDING" { + t.Errorf("expected a still-live-after-cancel booking checkout left 'PENDING' (never marked failed), got %q", status) + } + + // A CRITICAL admin notification against the booking must be raised so an + // operator verifies the Square checkout state manually. + var notifCount int + if err := db.Conn.QueryRow(freshCtx, `SELECT COUNT(*) FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id = $1 AND user_id IS NULL`, bookingID).Scan(¬ifCount); err != nil { + t.Fatalf("failed to count critical notifications: %v", err) + } + if notifCount != 1 { + t.Errorf("expected exactly 1 CRITICAL admin notification for the still-live-after-cancel booking checkout, got %d", notifCount) } } @@ -3712,3 +3953,513 @@ func TestSweepStaleTerminalCheckouts_CancelledBooking_NoPaymentRecorded(t *testi t.Errorf("expected a critical-payment admin notification for the cancelled booking, got %d", notifCount) } } + +// ============================================================================= +// Bug fixes: C3 cancel-recheck clawback, M2 stranded-charge auto-refund, M5 +// sweep-rescue VAT, M3 age-guard clock-source boundary, MINOR replay upper-bound +// skew +// ============================================================================= + +// terminalRecheckClient simulates the C3 "cancel then charge completes" race: a +// customer completes the payment at the terminal between the sweep's first +// GetCheckout (still live) and its post-cancel re-check (now COMPLETED). Every +// other call delegates to the real mock. +type terminalRecheckClient struct { + square.SquareClient + checkoutID string + calls int +} + +func (c *terminalRecheckClient) GetCheckout(ctx context.Context, checkoutID string) (*square.PaymentResult, error) { + if checkoutID == c.checkoutID { + c.calls++ + if c.calls == 1 { + return nil, square.ErrCheckoutPending + } + return &square.PaymentResult{Status: "COMPLETED", SquarePayID: "sqp_cancel_then_completed", Amount: 5000}, nil + } + return c.SquareClient.GetCheckout(ctx, checkoutID) +} + +// TestSweepStaleTerminalCheckouts_CancelThenChargeCompletes_FundingKept locks +// the C3 money-safety end-state: the sweep cancels a stale till-sale checkout +// but the customer completes the payment in the cancel window. The charge +// landed, so the sweep must RECONCILE (record the sale completed, keep the +// funded gift card) — never claw the funding back. The pre-fix code clawed the +// funding back on any cancel-recheck that was not COMPLETED, taking the +// customer's card money AND the gift-card value (silent money-taken). +func TestSweepStaleTerminalCheckouts_CancelThenChargeCompletes_FundingKept(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + adminID, err := fixtures.CreateTestAdminUser(tx) + if err != nil { + t.Fatalf("failed to create admin user: %v", err) + } + pool := context.Background() + + const checkoutID = "chk_cancel_then_completes" + saleID, giftCardID := seedStaleTerminalTillSale(t, ctx, tx, adminID, true) + if _, err := tx.Exec(ctx, `UPDATE till_sales SET square_checkout_id = $1 WHERE id = $2`, checkoutID, saleID); err != nil { + t.Fatalf("failed to set checkout id: %v", err) + } + if _, err := tx.Exec(ctx, ` + INSERT INTO gift_card_transactions (gift_card_id, transaction_type, amount, reference_type, reference_id) + VALUES ($1, 'purchase', 50.00, 'till_sale', $2) + `, giftCardID, saleID); err != nil { + t.Fatalf("failed to seed gift card transaction: %v", err) + } + + origClient := SquareClient + SquareClient = &terminalRecheckClient{SquareClient: square.NewDevClient(), checkoutID: checkoutID} + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit setup tx: %v", err) + } + + if _, err := db.Conn.Exec(pool, `DELETE FROM till_sales WHERE status = 'pending' AND square_checkout_id IS NOT NULL AND id <> $1`, saleID); err != nil { + t.Fatalf("failed to clean leftover stale terminal sales: %v", err) + } + if _, err := db.Conn.Exec(pool, `DELETE FROM terminal_checkouts WHERE status IN ('PENDING', 'IN_PROGRESS')`); err != nil { + t.Fatalf("failed to clean leftover stale booking terminal checkouts: %v", err) + } + + n, err := SweepStaleTerminalCheckouts(pool) + if err != nil { + t.Fatalf("sweep failed: %v", err) + } + if n != 1 { + t.Errorf("expected exactly 1 resolved stale terminal checkout (completed during cancel), got %d", n) + } + + // The sale must be RECONCILED to completed with the real charge recorded. + var status, sqPayID string + if err := db.Conn.QueryRow(pool, `SELECT status, COALESCE(square_payment_id, '') FROM till_sales WHERE id = $1`, saleID).Scan(&status, &sqPayID); err != nil { + t.Fatalf("failed to query till sale: %v", err) + } + if status != "completed" || sqPayID != "sqp_cancel_then_completed" { + t.Errorf("expected the cancel-then-completed sale recorded completed with the payment id, got status=%q sq_pay_id=%q", status, sqPayID) + } + + // The funded gift card must NOT have been clawed back. + var cardCount int + var remaining float64 + if err := db.Conn.QueryRow(pool, `SELECT COUNT(*), COALESCE(MAX(amount_remaining), 0) FROM gift_cards WHERE id = $1`, giftCardID).Scan(&cardCount, &remaining); err != nil { + t.Fatalf("failed to query gift card: %v", err) + } + if cardCount != 1 || remaining != 50.00 { + t.Errorf("expected the funded gift card kept after the completed charge, got count=%d remaining=%.2f", cardCount, remaining) + } +} + +// TestSweepStalePendingPayments_CancelledBooking_StrandedCharge_AutoRefundRow +// locks the M2 fix: a stale pending payment whose charge COMPLETED at Square on +// a booking that was cancelled during the pending window must not just be +// failed + admin-notified — an automatic cancellation refund row must be +// created for the full stranded charge so the pending-refund sweep issues the +// Square refund. The pre-fix code left the customer charged with NO automatic +// refund row. +func TestSweepStalePendingPayments_CancelledBooking_StrandedCharge_AutoRefundRow(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + userID, err := fixtures.CreateTestUser(tx) + if err != nil { + t.Fatalf("failed to create user: %v", err) + } + serviceID, err := fixtures.CreateTestService(tx) + if err != nil { + t.Fatalf("failed to create service: %v", err) + } + bookingID, err := fixtures.CreateTestBookingAtTime(tx, userID, serviceID, + time.Date(2099, 12, 31, 10, 0, 0, 0, time.UTC)) + if err != nil { + t.Fatalf("failed to create booking: %v", err) + } + // The booking was cancelled during the pending window. + if _, err := tx.Exec(ctx, "UPDATE bookings SET status = 'we_cancelled' WHERE id = $1", bookingID); err != nil { + t.Fatalf("failed to set booking we_cancelled: %v", err) + } + + staleID, err := fixtures.CreateTestPayment(tx, bookingID, 2000.00, "online_square", "full", "pending") + if err != nil { + t.Fatalf("failed to create stale pending payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET created_at = NOW() - INTERVAL '25 hours', created_by = $1 WHERE id = $2", userID, staleID); err != nil { + t.Fatalf("failed to age the stale payment: %v", err) + } + + origClient := SquareClient + mock := square.NewDevClient().(*square.MockClient) + pay, err := mock.CreatePayment(context.Background(), square.CreatePaymentReq{ + Amount: 200000, + Currency: "GBP", + SourceID: "cnon:test-card", + IdempotencyKey: "seed-stale-cancelled-booking", + }) + if err != nil { + t.Fatalf("failed to seed completed Square payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET square_payment_id = $1 WHERE id = $2", pay.SquarePayID, staleID); err != nil { + t.Fatalf("failed to set square_payment_id: %v", err) + } + SquareClient = mock + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit test tx: %v", err) + } + + pool := context.Background() + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM refunds WHERE payment_id = $1`, staleID) + _, _ = db.Conn.Exec(pool, `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log' AND booking_id = $1`, bookingID) + _, _ = db.Conn.Exec(pool, `DELETE FROM payments WHERE id = $1`, staleID) + _, _ = db.Conn.Exec(pool, `DELETE FROM bookings WHERE id = $1`, bookingID) + _, _ = db.Conn.Exec(pool, `DELETE FROM services WHERE id = $1`, serviceID) + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, userID) + }) + + if _, err := SweepStalePendingPayments(pool); err != nil { + t.Fatalf("sweep failed: %v", err) + } + + // The payment must be marked FAILED (never completed on a cancelled booking). + var status string + if err := db.Conn.QueryRow(pool, "SELECT status FROM payments WHERE id = $1", staleID).Scan(&status); err != nil { + t.Fatalf("failed to query payment: %v", err) + } + if status != "failed" { + t.Errorf("expected the stranded charge's payment marked failed, got %q", status) + } + + // M2: an automatic cancellation refund row must exist for the full charge. + var refundCount int + var refundAmount float64 + var refundStatus, refundOrigin string + if err := db.Conn.QueryRow(pool, ` + SELECT COUNT(*), COALESCE(MAX(amount), 0), COALESCE(MAX(status)::text, ''), COALESCE(MAX(origin), '') + FROM refunds WHERE payment_id = $1 + `, staleID).Scan(&refundCount, &refundAmount, &refundStatus, &refundOrigin); err != nil { + t.Fatalf("failed to query refund row: %v", err) + } + if refundCount != 1 { + t.Fatalf("expected exactly 1 automatic refund row for the stranded charge, got %d", refundCount) + } + if refundStatus != "pending" || refundOrigin != "cancellation" { + t.Errorf("expected a pending origin='cancellation' refund row (picked up by the refund sweep), got status=%q origin=%q", refundStatus, refundOrigin) + } + if refundAmount != 2000.00 { + t.Errorf("expected the refund row to cover the full stranded charge £2000.00, got £%.2f", refundAmount) + } +} + +// TestSweepStalePendingPayments_TillRescued_VATApplied locks the M5 fix: a stale +// pending till sale whose charge COMPLETED at Square is rescued to 'completed' +// by the sweep, and the sweep applies the SAME VAT the synchronous +// till-completion path (GetTillCheckoutStatus → ApplyVATToTillSale) would. The +// pre-fix sweep rescued the sale with its VAT fields untouched (NULL), silently +// dropping the sale from VAT reporting. +func TestSweepStalePendingPayments_TillRescued_VATApplied(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + adminID, err := fixtures.CreateTestAdminUser(tx) + if err != nil { + t.Fatalf("failed to create admin user: %v", err) + } + // VAT-registered, SPV vouchers — the config the synchronous path uses. + if _, err := tx.Exec(ctx, `UPDATE business_settings SET is_vat_registered = TRUE, default_vat_rate = 20.00, voucher_type = 'SPV'`); err != nil { + t.Fatalf("failed to enable VAT in business_settings: %v", err) + } + + origClient := SquareClient + mock := square.NewDevClient().(*square.MockClient) + pay, err := mock.CreatePayment(context.Background(), square.CreatePaymentReq{ + Amount: 5000, + Currency: "GBP", + SourceID: "cnon:test-card", + IdempotencyKey: "seed-stale-till-vat", + }) + if err != nil { + t.Fatalf("failed to seed completed Square payment: %v", err) + } + SquareClient = mock + defer func() { SquareClient = origClient }() + + var saleID string + err = tx.QueryRow(ctx, ` + INSERT INTO till_sales (item_type, description, quantity, unit_price, total_amount, payment_method, status, square_payment_id, created_by, created_at, updated_at) + VALUES ('gift_card', 'Gift Card create', 1, 50.00, 50.00, 'online_square', 'pending', $1, $2, NOW() - INTERVAL '25 hours', NOW()) + RETURNING id + `, pay.SquarePayID, adminID).Scan(&saleID) + if err != nil { + t.Fatalf("failed to seed stale pending till sale: %v", err) + } + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit test tx: %v", err) + } + + pool := context.Background() + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM till_sales WHERE id = $1`, saleID) + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, adminID) + _, _ = db.Conn.Exec(pool, `UPDATE business_settings SET is_vat_registered = FALSE, voucher_type = 'SPV'`) + }) + + if _, err := SweepStalePendingPayments(pool); err != nil { + t.Fatalf("sweep failed: %v", err) + } + + var status string + if err := db.Conn.QueryRow(pool, "SELECT status FROM till_sales WHERE id = $1", saleID).Scan(&status); err != nil { + t.Fatalf("failed to query till sale: %v", err) + } + if status != "completed" { + t.Fatalf("expected genuinely-charged stale till sale rescued to 'completed', got %q", status) + } + + // M5: the rescued sale must carry the SAME VAT fields the synchronous path + // computes — £50.00 at 20% → £8.33 VAT, £41.67 net. + var isVATApplicable bool + var vatAmount, netAmount, vatRate sql.NullFloat64 + if err := db.Conn.QueryRow(pool, `SELECT is_vat_applicable, vat_amount, net_amount, vat_rate FROM till_sales WHERE id = $1`, saleID).Scan(&isVATApplicable, &vatAmount, &netAmount, &vatRate); err != nil { + t.Fatalf("failed to query till sale VAT fields: %v", err) + } + if !isVATApplicable { + t.Errorf("expected is_vat_applicable=TRUE on the sweep-rescued till sale, got false") + } + if !vatAmount.Valid || vatAmount.Float64 != 8.33 { + t.Errorf("expected vat_amount 8.33 on the sweep-rescued till sale, got %v", vatAmount) + } + if !netAmount.Valid || netAmount.Float64 != 41.67 { + t.Errorf("expected net_amount 41.67 on the sweep-rescued till sale, got %v", netAmount) + } + if !vatRate.Valid || vatRate.Float64 != 20.00 { + t.Errorf("expected vat_rate 20.00 on the sweep-rescued till sale, got %v", vatRate) + } +} + +// TestSweepStalePendingPayments_AgeBoundary_23h_24h locks the M3 clock-source +// contract at the sweep's stale-age boundary: every age-guard cutoff in this +// package is computed from clock.Now() (never a DB NOW()-derived comparison), +// so a row aged just UNDER stalePendingPaymentAge (24h) stays pending and a row +// aged just OVER it is swept — with a comfortable margin so the two clocks +// (DB NOW() at write, clock.Now() at cutoff) can never flip the decision at the +// boundary. +func TestSweepStalePendingPayments_AgeBoundary_23h_24h(t *testing.T) { + ctx, tx := testutils.SetupTestTx(t) + + userID, err := fixtures.CreateTestUser(tx) + if err != nil { + t.Fatalf("failed to create user: %v", err) + } + serviceID, err := fixtures.CreateTestService(tx) + if err != nil { + t.Fatalf("failed to create service: %v", err) + } + bookingID, err := fixtures.CreateTestBookingAtTime(tx, userID, serviceID, + time.Date(2099, 12, 31, 10, 0, 0, 0, time.UTC)) + if err != nil { + t.Fatalf("failed to create booking: %v", err) + } + + youngID, err := fixtures.CreateTestPayment(tx, bookingID, 2000.00, "online_square", "full", "pending") + if err != nil { + t.Fatalf("failed to create young pending payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET created_at = NOW() - INTERVAL '23 hours 50 minutes', square_payment_id = 'sqp_age_young' WHERE id = $1", youngID); err != nil { + t.Fatalf("failed to age the young payment: %v", err) + } + oldID, err := fixtures.CreateTestPayment(tx, bookingID, 2000.00, "online_square", "full", "pending") + if err != nil { + t.Fatalf("failed to create old pending payment: %v", err) + } + if _, err := tx.Exec(ctx, "UPDATE payments SET created_at = NOW() - INTERVAL '24 hours 10 minutes', square_payment_id = 'sqp_age_old' WHERE id = $1", oldID); err != nil { + t.Fatalf("failed to age the old payment: %v", err) + } + + origClient := SquareClient + mock := square.NewDevClient() + SquareClient = mock + defer func() { SquareClient = origClient }() + + pgxTx := db.TxFromContext(ctx) + if pgxTx == nil { + t.Fatal("no transaction in context") + } + if err := pgxTx.Commit(ctx); err != nil { + t.Fatalf("failed to commit test tx: %v", err) + } + + pool := context.Background() + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM payments WHERE id = ANY($1)`, []string{youngID, oldID}) + _, _ = db.Conn.Exec(pool, `DELETE FROM bookings WHERE id = $1`, bookingID) + _, _ = db.Conn.Exec(pool, `DELETE FROM services WHERE id = $1`, serviceID) + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, userID) + }) + + if _, err := SweepStalePendingPayments(pool); err != nil { + t.Fatalf("sweep failed: %v", err) + } + + // Under the 24h cutoff: not stale, stays pending. + var youngStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM payments WHERE id = $1", youngID).Scan(&youngStatus); err != nil { + t.Fatalf("failed to query young payment: %v", err) + } + if youngStatus != "pending" { + t.Errorf("expected a 23h50m-old payment (under the 24h cutoff) to stay pending, got %q", youngStatus) + } + + // Over the 24h cutoff: stale, swept to failed (Square has no such payment). + var oldStatus string + if err := db.Conn.QueryRow(pool, "SELECT status FROM payments WHERE id = $1", oldID).Scan(&oldStatus); err != nil { + t.Fatalf("failed to query old payment: %v", err) + } + if oldStatus != "failed" { + t.Errorf("expected a 24h10m-old payment (over the 24h cutoff) swept to failed, got %q", oldStatus) + } +} + +// TestReplayWithinLegitimateWindow_UpperBoundSkew locks the MINOR fix: the +// upper-bound discriminator ("same charge vs the sweep's own replay-created new +// charge") tolerates a small clock skew — a replayed COMPLETED payment created +// within replayRescueUpperBoundSkew (5s) AFTER the sweep's replay instant is +// still a legit original/retry and must be rescued, while one created beyond +// the skew is a provably-new expired-key duplicate. Exercised directly because +// replayRevealsNewCharge is gated off in the dev/mock test env. +func TestReplayWithinLegitimateWindow_UpperBoundSkew(t *testing.T) { + rowCreated := time.Date(2026, 8, 1, 10, 0, 0, 0, time.UTC) + replayAt := rowCreated.Add(22 * time.Hour) + base := staleRow{CreatedAt: rowCreated, AmountPence: 5000} + + // A payment created just inside the 5s upper-bound skew AFTER the replay is + // a legit same-key retry whose Square timestamp reads slightly ahead of the + // app clock — must be rescued, never auto-refunded. + within := &square.PaymentResult{Status: "COMPLETED", Amount: 5000, CreatedAt: replayAt.Add(4 * time.Second).Format(time.RFC3339Nano)} + if !replayWithinLegitimateWindow(base, replayAt, within) { + t.Errorf("expected a payment created %s after the replay (within the %s skew) to be legitimate", replayRescueUpperBoundSkew, replayRescueUpperBoundSkew) + } + + // A payment created just beyond the skew is the sweep's own replay-created + // expired-key duplicate — must NOT be rescued. + beyond := &square.PaymentResult{Status: "COMPLETED", Amount: 5000, CreatedAt: replayAt.Add(6 * time.Second).Format(time.RFC3339Nano)} + if replayWithinLegitimateWindow(base, replayAt, beyond) { + t.Errorf("expected a payment created 6s after the replay (beyond the %s skew) to be a NEW charge, got legitimate", replayRescueUpperBoundSkew) + } + + // A payment created just BEFORE the replay is the original/retry — rescued. + before := &square.PaymentResult{Status: "COMPLETED", Amount: 5000, CreatedAt: replayAt.Add(-1 * time.Second).Format(time.RFC3339Nano)} + if !replayWithinLegitimateWindow(base, replayAt, before) { + t.Errorf("expected a payment created 1s before the replay to be legitimate") + } + + // A DIFFERENT amount can never be the charge this row is waiting on. + wrongAmount := &square.PaymentResult{Status: "COMPLETED", Amount: 4999, CreatedAt: replayAt.Add(-1 * time.Second).Format(time.RFC3339Nano)} + if replayWithinLegitimateWindow(base, replayAt, wrongAmount) { + t.Errorf("expected a replayed payment with a different amount to be refused") + } +} + +// TestInsertCriticalPaymentNotification_FloodCap_ConcurrentSerialized locks the +// F6 serialization of the flood cap: the count-then-insert critical section in +// insertCriticalPaymentNotification runs inside a transaction scoped by +// pg_advisory_xact_lock, so even when many inserts fire concurrently at the cap +// boundary the unacknowledged critical_payment_log queue never exceeds +// adminnotify.MaxUnacknowledgedCriticalLogs. Under READ COMMITTED a bare +// count-then-insert would let every concurrent insert evaluate the COUNT before +// any of them commits and overshoot by the concurrency. +func TestInsertCriticalPaymentNotification_FloodCap_ConcurrentSerialized(t *testing.T) { + pool := context.Background() + + userID, err := fixtures.CreateTestUser(db.Conn) + if err != nil { + t.Fatalf("failed to create user: %v", err) + } + // One committed booking per notification so the per-issue NOT EXISTS dedup + // does not collapse distinct inserts (and the booking_id FK resolves — the + // helper's insert runs in its own pool transaction, so the rows must be + // committed first). + const concurrent = 6 + total := adminnotify.MaxUnacknowledgedCriticalLogs - 1 + concurrent + var bookingIDs []string + for i := 0; i < total; i++ { + var bookingID string + if err := db.Conn.QueryRow(pool, ` + INSERT INTO bookings (user_id, start_time, status, notes) + VALUES ($1, NOW() + INTERVAL '1 day', 'pending', 'flood-cap serialization test') + RETURNING id + `, userID).Scan(&bookingID); err != nil { + t.Fatalf("failed to create booking %d: %v", i, err) + } + bookingIDs = append(bookingIDs, bookingID) + } + // This test runs in the sequential phase (it never calls t.Parallel), so no + // other test is active while it runs: clearing the whole queue at setup and + // in cleanup is safe and makes the cap-boundary math deterministic. Without + // the clear, a leftover notification from an earlier test would trip the + // helper's global pre-check and suppress every concurrent insert. + t.Cleanup(func() { + _, _ = db.Conn.Exec(pool, `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'`) + for _, b := range bookingIDs { + _, _ = db.Conn.Exec(pool, `DELETE FROM bookings WHERE id = $1`, b) + } + _, _ = db.Conn.Exec(pool, `DELETE FROM users WHERE id = $1`, userID) + }) + if _, err := db.Conn.Exec(pool, `DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'`); err != nil { + t.Fatalf("failed to clear the critical notification queue: %v", err) + } + + // Seed the queue to one below the cap, each with its own booking. + for i := 0; i < adminnotify.MaxUnacknowledgedCriticalLogs-1; i++ { + if _, err := db.Conn.Exec(pool, ` + INSERT INTO admin_notifications (reason, booking_id, user_id, created_at) + VALUES ('critical_payment_log', $1, NULL, NOW()) + `, bookingIDs[i]); err != nil { + t.Fatalf("failed to seed notification %d: %v", i, err) + } + } + + // Fire `concurrent` inserts at the boundary simultaneously. With the + // advisory xact lock exactly ONE of them lands (the first to hold the lock + // sees the count still below the cap); every waiter's COUNT runs after the + // previous insert committed, so the rest see the cap reached and are + // suppressed. + start := make(chan struct{}) + var wg sync.WaitGroup + for i := 0; i < concurrent; i++ { + b := bookingIDs[adminnotify.MaxUnacknowledgedCriticalLogs-1+i] + wg.Add(1) + go func(booking string) { + defer wg.Done() + <-start + insertCriticalPaymentNotification(pool, &booking, nil) + }(b) + } + close(start) + wg.Wait() + + var totalUnacked int + if err := db.Conn.QueryRow(pool, ` + SELECT COUNT(*) FROM admin_notifications + WHERE reason = 'critical_payment_log' AND acknowledged_at IS NULL + `).Scan(&totalUnacked); err != nil { + t.Fatalf("failed to count notifications: %v", err) + } + if totalUnacked != adminnotify.MaxUnacknowledgedCriticalLogs { + t.Errorf("expected the unacknowledged queue capped at exactly %d under concurrent inserts (serialized), got %d", adminnotify.MaxUnacknowledgedCriticalLogs, totalUnacked) + } +} diff --git a/backend/handlers/webhooks/webhooks_completion_asymmetry_test.go b/backend/handlers/webhooks/webhooks_completion_asymmetry_test.go new file mode 100644 index 0000000..cd174a0 --- /dev/null +++ b/backend/handlers/webhooks/webhooks_completion_asymmetry_test.go @@ -0,0 +1,140 @@ +//go:build test + +package webhooks + +// M15 webhook-completion idempotency, exercised through the REAL +// HandleSquareWebhook handler. The webhook's payment.updated completion path +// (handlePaymentUpdated) and the payments package's stale-pending sweep rescue +// can both try to complete the same payment; both flip status only while the +// row is still 'pending', so the first writer wins and the second applies no +// side effects. This test drives the real handler twice (distinct event ids, +// so the dedup cache does not swallow the replay) and then runs the real sweep, +// asserting the payment completes exactly once and the sweep adds nothing. + +import ( + "context" + "encoding/json" + "net/http" + "testing" + "time" + + "crussell/db" + "crussell/handlers/payments" + "crussell/testutils/fixtures" +) + +// TestWebhook_AndSweep_DoNotDoubleComplete locks the webhook-first race +// ordering end to end through the real HTTP handler: the first +// payment.updated COMPLETED delivery completes the pending row; the second +// delivery is a no-op (the row is no longer pending) and the sweep rescue +// path, which runs after, finds nothing pending and applies no side effects. +func TestWebhook_AndSweep_DoNotDoubleComplete(t *testing.T) { + userID, err := fixtures.CreateTestUser(db.Conn) + if err != nil { + t.Fatalf("failed to create user: %v", err) + } + serviceID, err := fixtures.CreateTestService(db.Conn) + if err != nil { + t.Fatalf("failed to create service: %v", err) + } + bookingID, err := fixtures.CreateTestBookingAtTime(db.Conn, userID, serviceID, + time.Date(2099, 12, 31, 10, 0, 0, 0, time.UTC)) + if err != nil { + t.Fatalf("failed to create booking: %v", err) + } + + const squarePaymentID = "sqp_webhook_and_sweep" + payID := createWebhookTestPayment(t, squarePaymentID, "pending") + if _, err := db.Conn.Exec(context.Background(), + "UPDATE payments SET booking_id = $1, created_at = NOW() - INTERVAL '25 hours' WHERE id = $2", + bookingID, payID); err != nil { + t.Fatalf("failed to attach booking and age the payment: %v", err) + } + // Give the booking a payable total so a (hypothetical) rescue-side + // completion check would complete it — proving the sweep does NOT run it + // after the webhook already settled the row. + if _, err := db.Conn.Exec(context.Background(), + "UPDATE bookings SET total_amount = 10.00 WHERE id = $1", bookingID); err != nil { + t.Fatalf("failed to set booking total: %v", err) + } + + // The sweep reads the payments package's exported SquareClient. Under the + // `test,!dev` CI shape there is no dev mock to install, so guarantee the + // sweep is a true no-op for OUR row instead: the row is already completed + // (never fetched) and every OTHER stale pending row in this package's test + // DB is deleted up front, so no reconcile ever touches SquareClient. + if _, err := db.Conn.Exec(context.Background(), + "DELETE FROM payments WHERE status = 'pending' AND created_at < NOW() - INTERVAL '24 hours' AND id <> $1", + payID); err != nil { + t.Fatalf("failed to clear leftover stale pending payments: %v", err) + } + if _, err := db.Conn.Exec(context.Background(), + "DELETE FROM till_sales WHERE status = 'pending' AND created_at < NOW() - INTERVAL '24 hours'"); err != nil { + t.Fatalf("failed to clear leftover stale pending till sales: %v", err) + } + + // 1. First payment.updated COMPLETED delivery → completes the pending row. + event := SquareWebhookEvent{ + Type: "payment.updated", + EventID: "evt_webhook_and_sweep_1", + CreatedAt: "2025-01-01T00:00:00Z", + Data: json.RawMessage(`{ + "type": "payment", + "id": "` + squarePaymentID + `", + "object": { + "payment": { + "id": "` + squarePaymentID + `", + "status": "COMPLETED" + } + } + }`), + } + w := deliverWebhook(t, event) + if w.Code != http.StatusOK { + t.Fatalf("expected 200 on the first delivery, got %d: %s", w.Code, w.Body.String()) + } + if got := getPaymentStatus(t, payID); got != "completed" { + t.Fatalf("expected the first webhook delivery to complete the payment, got %q", got) + } + + // 2. Second delivery (distinct event id — the dedup cache is bypassed): + // the row is already completed, so the pending-only UPDATE matches nothing. + event2 := event + event2.EventID = "evt_webhook_and_sweep_2" + w2 := deliverWebhook(t, event2) + if w2.Code != http.StatusOK { + t.Fatalf("expected 200 on the replay delivery, got %d: %s", w2.Code, w2.Body.String()) + } + if got := getPaymentStatus(t, payID); got != "completed" { + t.Errorf("expected the replay delivery to leave the payment completed, got %q", got) + } + + // 3. The sweep's rescue path runs after the webhook already completed the + // row: the row is no longer 'pending', so the sweep never fetches it and + // never applies its completion side effects. + if _, err := payments.SweepStalePendingPayments(context.Background()); err != nil { + t.Fatalf("sweep failed: %v", err) + } + if got := getPaymentStatus(t, payID); got != "completed" { + t.Errorf("expected the sweep to leave the webhook-completed payment alone, got %q", got) + } + + // No split records / completion side effects may have been applied by the + // sweep (the rescue is gated on the row still pending). + var recordCount int + if err := db.Conn.QueryRow(context.Background(), + "SELECT COUNT(*) FROM payments WHERE booking_id = $1", bookingID).Scan(&recordCount); err != nil { + t.Fatalf("failed to count payment records: %v", err) + } + if recordCount != 1 { + t.Errorf("expected exactly the one webhook-completed payment row (no sweep splits), got %d", recordCount) + } + var bookingStatus string + if err := db.Conn.QueryRow(context.Background(), + "SELECT status FROM bookings WHERE id = $1", bookingID).Scan(&bookingStatus); err != nil { + t.Fatalf("failed to query booking: %v", err) + } + if bookingStatus != "pending" { + t.Errorf("expected the sweep not to complete the booking after the webhook settled the row, got %q", bookingStatus) + } +}