From 2a47021673afb2bf906e734c17211722a5868048 Mon Sep 17 00:00:00 2001 From: Stephen Adamson Date: Sun, 16 Aug 2026 00:16:41 +0100 Subject: [PATCH] =?UTF-8?q?fix:=20stale-pending=20sweep=20hardening=20?= =?UTF-8?q?=E2=80=94=20auto-refund=20stranded=20charges=20(M2),=20VAT=20re?= =?UTF-8?q?-apply=20(M5),=20single=20clock=20source=20(M3)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - M2: a stale pending payment COMPLETED at Square on a cancelled/lapsed/no-show booking no longer just fails the row + admin-notifies: an automatic pending refund row for the full stranded charge is created (same shape/origin as ProcessCancellationRefundTx, deterministic idempotency key, square_payment_id written when missing) so the pending-refund sweep issues it at Square. - M5: sweep rescues re-apply VAT — rescued till sales run ApplyVATToTillSale and rescued payments apply ApplyVATToBookingPayment per record after the align UPDATE (which no longer NULLs the VAT fields), keeping rescued charges in VAT reporting. Both SQL functions are idempotent (guarded on vat_amount IS NULL). - M3: every age-guard cutoff in the sweep is computed from clock.Now() and passed into SQL as parameters (never a DB NOW()-derived comparison) so the 23h/24h Square idempotency-key retention decision cannot flip on clock skew; replayRescueUpperBoundSkew (5s) stops a legit same-key retry that raced the sweep from being misclassified as the sweep's own replay-created duplicate. - C2: till cash/giftcard charges now serialize under the same crussell:payment: advisory lock as the online path (bounded try-lock) so remaining-balance checks can never both pass. - webhooks_completion_asymmetry_test: webhook-first completion + sweep rescue double-complete race locked end-to-end through the real handler. --- backend/handlers/payments/sweep.go | 253 +++++- .../handlers/payments/sweep_boundary_test.go | 334 ++++++++ backend/handlers/payments/sweep_test.go | 787 +++++++++++++++++- .../webhooks_completion_asymmetry_test.go | 140 ++++ 4 files changed, 1462 insertions(+), 52 deletions(-) create mode 100644 backend/handlers/payments/sweep_boundary_test.go create mode 100644 backend/handlers/webhooks/webhooks_completion_asymmetry_test.go 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) + } +}