Surface unresolved critical payment states as admin notifications
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.
This commit is contained in:
@@ -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
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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,
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user