From 5605402e139e572ed9d037c6fac170184220616c Mon Sep 17 00:00:00 2001 From: Stephen Adamson Date: Mon, 3 Aug 2026 19:26:20 +0100 Subject: [PATCH] Surface unresolved critical payment states as admin notifications MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds the scan-critical-payment-logs job (daily 2:45am) that surfaces stale pending payments/till-sales and refunds at the retry cap as admin_notifications with reason='critical_payment_log' — the app has no log/alert pipeline (Gap Backlog T14), so money events that would otherwise sit in un-watched CRITICAL log lines now reach the owner's in-app notification centre. Dedup is NULL-safe (IS NOT DISTINCT FROM) and re-surfaces acknowledged-but-still-unresolved rows. Stopgap until a real alerting pipeline lands. --- backend/internal/jobs/cleanup.go | 80 ++++++++ backend/internal/jobs/cleanup_test.go | 236 ++++++++++++++++++++++++ backend/internal/jobs/scheduler_test.go | 5 +- 3 files changed, 319 insertions(+), 2 deletions(-) diff --git a/backend/internal/jobs/cleanup.go b/backend/internal/jobs/cleanup.go index a16e9b4..a227e19 100644 --- a/backend/internal/jobs/cleanup.go +++ b/backend/internal/jobs/cleanup.go @@ -4,6 +4,7 @@ import ( "context" "errors" "fmt" + "log" "log/slog" "time" @@ -231,6 +232,21 @@ func RegisterAll(s *Scheduler) { Concurrency: 1, Handler: SweepSquareWebhookEvents, }) + + // Surfaces unresolved money events (stale pending payments/till sales, + // refunds at the retry cap) as admin notifications so the owner sees the + // "money may have moved at Square but the DB couldn't record it" situations + // that would otherwise live only in un-watched CRITICAL log lines (Gap + // Backlog T14). Retire this job when a proper log/alert pipeline (T14 + // Sentry) lands — the notifications page is the stopgap while the app has + // none. Staggered at 2:45am between the 2am and 3am daily batches. + s.Register(Job{ + Name: "scan-critical-payment-logs", + Schedule: "45 2 * * *", // Daily at 2:45am + Timeout: 30 * time.Second, + Concurrency: 1, + Handler: ScanCriticalPaymentLogs, + }) } // SweepSquareWebhookEvents deletes square_webhook_events rows older than 90 @@ -259,3 +275,67 @@ func SweepSquareWebhookEvents(ctx context.Context) (int, error) { return int(tag.RowsAffected()), tx.Commit(ctx) } + +// criticalPaymentStaleAge is how long a pending payment / till sale may sit +// unresolved before the scan surfaces it to the admin notification centre. A +// pending row with no update in this window is exactly the "money may have +// moved at Square but the DB couldn't record it" situation the CRITICAL payment +// logs describe (handlers.go, giftcards.go, refunds.go, till.go). Deliberately +// shorter than the 24h stale-pending sweep (handlers/payments/sweep.go) so the +// owner hears about it while the row could still be rescued. +const criticalPaymentStaleAge = "2 hours" + +// ScanCriticalPaymentLogs surfaces unresolved critical payment states as admin +// notifications (reason='critical_payment_log'), giving the owner an in-app +// view of money events that would otherwise be visible only in un-watched +// CRITICAL log lines (the app has no log/alert pipeline — Gap Backlog T14). +// +// Candidates: +// - payments / till_sales rows still 'pending' with no update for >2h: a +// lost-response charge the DB never recorded. +// - refunds rows still 'pending' at the 3-attempt retry cap: a refund the +// sweep could not resolve (money may have moved at Square). +// +// Each candidate inserts one admin_notifications row keyed on (reason, +// booking_id) — but ONLY if no unacknowledged notification for that key +// already exists (NULL-safe via IS NOT DISTINCT FROM, matching the +// insertRefundFailedNotifications dedup in handlers/payments/refunds.go), so +// the bell never floods. Acknowledging the notification re-arms the scan: +// while the row stays unresolved it is surfaced again on the next run. +// +// This is the "grep CRITICAL" the audit asked for, but DB-backed since the app +// has no log pipeline. When a proper log/alert pipeline (T14 Sentry) lands, +// this job can be retired. +func ScanCriticalPaymentLogs(ctx context.Context) (int, error) { + tag, err := db.Conn.Exec(ctx, ` + INSERT INTO admin_notifications (reason, booking_id, created_at) + SELECT DISTINCT 'critical_payment_log'::admin_notification_reason, src.booking_id, NOW() + FROM ( + -- Lost-response payments: still pending with no update past the threshold. + SELECT id, booking_id FROM payments + WHERE status = 'pending' AND updated_at < NOW() - INTERVAL '`+criticalPaymentStaleAge+`' + UNION ALL + -- Lost-response till sales (no booking linkage — booking_id NULL). + SELECT id, NULL::CHAR(12) FROM till_sales + WHERE status = 'pending' AND updated_at < NOW() - INTERVAL '`+criticalPaymentStaleAge+`' + UNION ALL + -- Refunds stuck at the 3-attempt retry cap. + SELECT id, booking_id FROM refunds + WHERE status = 'pending' AND refund_attempts >= 3 + ) src + WHERE NOT EXISTS ( + SELECT 1 FROM admin_notifications an + WHERE an.reason = 'critical_payment_log' + AND an.booking_id IS NOT DISTINCT FROM src.booking_id + AND an.acknowledged_at IS NULL + ) + `) + if err != nil { + return 0, fmt.Errorf("failed to scan critical payment logs: %w", err) + } + n := int(tag.RowsAffected()) + if n > 0 { + log.Printf("[SCAN] Inserted %d admin_notification(s) for unresolved critical payment states (pending payments/till sales > %s, refunds at retry cap)", n, criticalPaymentStaleAge) + } + return n, nil +} diff --git a/backend/internal/jobs/cleanup_test.go b/backend/internal/jobs/cleanup_test.go index 1fd3df6..4d47643 100644 --- a/backend/internal/jobs/cleanup_test.go +++ b/backend/internal/jobs/cleanup_test.go @@ -87,3 +87,239 @@ func TestSweepSquareWebhookEvents_EmptyTable(t *testing.T) { t.Errorf("expected 0 rows deleted on empty table, got %d", n) } } + +// ============================================================ +// ScanCriticalPaymentLogs Tests +// ============================================================ + +// countCriticalPaymentLogs returns the number of 'critical_payment_log' +// admin_notifications currently in the shared test database. +func countCriticalPaymentLogs(ctx context.Context) int { + var n int + if err := db.Conn.QueryRow(ctx, + "SELECT COUNT(*) FROM admin_notifications WHERE reason = 'critical_payment_log'").Scan(&n); err != nil { + return -1 + } + return n +} + +// seedStalePendingPayment inserts a payments row still 'pending' with no update +// past the scan threshold (the "money may have moved at Square but the DB never +// recorded it" situation). +func seedStalePendingPayment(t *testing.T) string { + t.Helper() + ctx := context.Background() + var id string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO payments (booking_id, payment_type, payment_method, status, amount, created_at, updated_at) + VALUES (NULL, 'full', 'online_square', 'pending', 50.00, + NOW() - INTERVAL '3 hours', NOW() - INTERVAL '3 hours') + RETURNING id`).Scan(&id); err != nil { + t.Fatalf("failed to seed stale pending payment: %v", err) + } + return id +} + +// TestScanCriticalPaymentLogs_StalePendingPayment verifies a payments row still +// 'pending' with no update past the threshold surfaces one admin notification. +func TestScanCriticalPaymentLogs_StalePendingPayment(t *testing.T) { + ctx := context.Background() + paymentID := seedStalePendingPayment(t) + t.Cleanup(func() { + _, _ = db.Conn.Exec(ctx, "DELETE FROM payments WHERE id = $1", paymentID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'") + }) + + n, err := ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("ScanCriticalPaymentLogs failed: %v", err) + } + if n != 1 { + t.Errorf("expected 1 notification inserted, got %d", n) + } + if got := countCriticalPaymentLogs(ctx); got != 1 { + t.Errorf("expected 1 critical_payment_log notification, got %d", got) + } +} + +// TestScanCriticalPaymentLogs_FreshPendingPaymentNotNotified verifies a pending +// payment updated within the threshold is NOT surfaced — only rows stuck past +// the threshold represent an unresolved money event. +func TestScanCriticalPaymentLogs_FreshPendingPaymentNotNotified(t *testing.T) { + ctx := context.Background() + var paymentID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO payments (booking_id, payment_type, payment_method, status, amount, created_at, updated_at) + VALUES (NULL, 'full', 'online_square', 'pending', 50.00, NOW(), NOW()) + RETURNING id`).Scan(&paymentID); err != nil { + t.Fatalf("failed to seed fresh pending payment: %v", err) + } + t.Cleanup(func() { + _, _ = db.Conn.Exec(ctx, "DELETE FROM payments WHERE id = $1", paymentID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'") + }) + + n, err := ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("ScanCriticalPaymentLogs failed: %v", err) + } + if n != 0 { + t.Errorf("expected 0 notifications for a fresh pending payment, got %d", n) + } +} + +// TestScanCriticalPaymentLogs_StalePendingTillSale verifies the till_sales scan +// (no booking linkage — the notification carries a NULL booking_id). +func TestScanCriticalPaymentLogs_StalePendingTillSale(t *testing.T) { + ctx := context.Background() + + var userID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO users (n_first_name, n_last_name, phone, date_of_birth) + VALUES ('Test', 'Till', '+447700900123', '1990-01-01') + RETURNING id`).Scan(&userID); err != nil { + t.Fatalf("failed to seed till user: %v", err) + } + var saleID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO till_sales (item_type, description, quantity, unit_price, total_amount, payment_method, status, created_by, created_at, updated_at) + VALUES ('gift_card', 'gift card', 1, 25.00, 25.00, 'online_square', 'pending', $1, + NOW() - INTERVAL '3 hours', NOW() - INTERVAL '3 hours') + RETURNING id`, userID).Scan(&saleID); err != nil { + t.Fatalf("failed to seed stale pending till sale: %v", err) + } + t.Cleanup(func() { + _, _ = db.Conn.Exec(ctx, "DELETE FROM till_sales WHERE id = $1", saleID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM users WHERE id = $1", userID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'") + }) + + n, err := ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("ScanCriticalPaymentLogs failed: %v", err) + } + if n != 1 { + t.Errorf("expected 1 notification inserted, got %d", n) + } +} + +// TestScanCriticalPaymentLogs_DedupAndReArm verifies the dedup guard: a second +// scan while an unacknowledged notification exists inserts nothing, but +// acknowledging the notification re-arms the scan while the row stays +// unresolved (the problem is still present, so it is surfaced again). +func TestScanCriticalPaymentLogs_DedupAndReArm(t *testing.T) { + ctx := context.Background() + paymentID := seedStalePendingPayment(t) + t.Cleanup(func() { + _, _ = db.Conn.Exec(ctx, "DELETE FROM payments WHERE id = $1", paymentID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'") + }) + + n, err := ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("first scan failed: %v", err) + } + if n != 1 { + t.Fatalf("expected 1 notification on first scan, got %d", n) + } + + // Unacknowledged notification present → the second scan must insert nothing. + n, err = ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("second scan failed: %v", err) + } + if n != 0 { + t.Errorf("expected 0 notifications on re-scan while unacknowledged, got %d", n) + } + if got := countCriticalPaymentLogs(ctx); got != 1 { + t.Errorf("expected exactly 1 notification after dedup, got %d", got) + } + + // Acknowledging re-arms the scan while the row stays unresolved. + if _, err := db.Conn.Exec(ctx, "UPDATE admin_notifications SET acknowledged_at = NOW() WHERE reason = 'critical_payment_log'"); err != nil { + t.Fatalf("failed to acknowledge notification: %v", err) + } + n, err = ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("third scan failed: %v", err) + } + if n != 1 { + t.Errorf("expected 1 notification re-inserted after acknowledge, got %d", n) + } + if got := countCriticalPaymentLogs(ctx); got != 2 { + t.Errorf("expected 2 notifications after re-arm, got %d", got) + } +} + +// TestScanCriticalPaymentLogs_RefundAtAttemptCap verifies a refund still +// 'pending' at the 3-attempt retry cap surfaces a notification (money may have +// moved at Square but the refund outcome was never recorded). +func TestScanCriticalPaymentLogs_RefundAtAttemptCap(t *testing.T) { + ctx := context.Background() + + var paymentID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO payments (booking_id, payment_type, payment_method, status, amount) + VALUES (NULL, 'full', 'online_square', 'completed', 50.00) + RETURNING id`).Scan(&paymentID); err != nil { + t.Fatalf("failed to seed payment for refund: %v", err) + } + var refundID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO refunds (payment_id, amount, status, refund_attempts, reason) + VALUES ($1, 10.00, 'pending', 3, 'customer request') + RETURNING id`, paymentID).Scan(&refundID); err != nil { + t.Fatalf("failed to seed refund at attempt cap: %v", err) + } + t.Cleanup(func() { + _, _ = db.Conn.Exec(ctx, "DELETE FROM refunds WHERE id = $1", refundID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM payments WHERE id = $1", paymentID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'") + }) + + n, err := ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("ScanCriticalPaymentLogs failed: %v", err) + } + if n != 1 { + t.Errorf("expected 1 notification inserted, got %d", n) + } + if got := countCriticalPaymentLogs(ctx); got != 1 { + t.Errorf("expected 1 critical_payment_log notification, got %d", got) + } +} + +// TestScanCriticalPaymentLogs_RefundBelowCapNotNotified verifies only refunds at +// the 3-attempt cap are surfaced; a pending refund with retries remaining is +// still being worked by the refund sweep. +func TestScanCriticalPaymentLogs_RefundBelowCapNotNotified(t *testing.T) { + ctx := context.Background() + + var paymentID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO payments (booking_id, payment_type, payment_method, status, amount) + VALUES (NULL, 'full', 'online_square', 'completed', 50.00) + RETURNING id`).Scan(&paymentID); err != nil { + t.Fatalf("failed to seed payment for refund: %v", err) + } + var refundID string + if err := db.Conn.QueryRow(ctx, ` + INSERT INTO refunds (payment_id, amount, status, refund_attempts, reason) + VALUES ($1, 10.00, 'pending', 1, 'customer request') + RETURNING id`, paymentID).Scan(&refundID); err != nil { + t.Fatalf("failed to seed refund below attempt cap: %v", err) + } + t.Cleanup(func() { + _, _ = db.Conn.Exec(ctx, "DELETE FROM refunds WHERE id = $1", refundID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM payments WHERE id = $1", paymentID) + _, _ = db.Conn.Exec(ctx, "DELETE FROM admin_notifications WHERE reason = 'critical_payment_log'") + }) + + n, err := ScanCriticalPaymentLogs(ctx) + if err != nil { + t.Fatalf("ScanCriticalPaymentLogs failed: %v", err) + } + if n != 0 { + t.Errorf("expected 0 notifications for a refund below the attempt cap, got %d", n) + } +} diff --git a/backend/internal/jobs/scheduler_test.go b/backend/internal/jobs/scheduler_test.go index b9356f9..5fda107 100644 --- a/backend/internal/jobs/scheduler_test.go +++ b/backend/internal/jobs/scheduler_test.go @@ -413,8 +413,8 @@ func TestRegisterAll_RegistersExpectedJobs(t *testing.T) { s := New() RegisterAll(s) - if got := len(s.registry); got != 24 { - t.Fatalf("RegisterAll() registered %d jobs, want 24", got) + if got := len(s.registry); got != 25 { + t.Fatalf("RegisterAll() registered %d jobs, want 25", got) } registered := make(map[string]Job, len(s.registry)) @@ -492,6 +492,7 @@ func expectedJobNames() map[string]bool { "cleanup-refresh-tokens": true, "sweep-square-webhook-events": true, "apply-default-hours": true, + "scan-critical-payment-logs": true, } }