amazon: replace fire-and-forget listener notifications with ack-based retry

Dispatching an event to the listener previously happened from an un-awaited goroutine, with only a log line on failure - once processed_at was set, a dropped or failed notification was permanently and silently lost, with no way to tell it had happened. Replaces the processed/processed_successfully booleans with a notified_at/processed_at pair (migration 000031): the dispatcher sets notified_at and hands the event to MockEventListener.Notify, which now also receives an ack callback the listener calls whenever it's truly done, synchronously or arbitrarily later. Anything still "notified" but unacked past notifyRetryAfter (a tunable field, not a stored per-row timestamp) gets notified again on the dispatcher's normal poll/reactive loop - no new retry mechanism needed. ack is idempotent, since a late ack from an earlier attempt and one from a retry can both eventually fire for the same event. Dispatch is deferred until after the transaction that recorded notified_at has actually committed, so ack's independent write can't race a still-open transaction it implicitly depends on being visible. The real SSE listener (server/sse/db_event_publisher.go) acks inline, since its work is synchronous. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01XEDaCB7C2NEBgyvqEtZuxY
2026-08-20 00:35:22 -06:00
parent 579eae5097
commit 984a4465f8
6 changed files with 346 additions and 48 deletions
@@ -14,25 +14,40 @@ import (
 )

 // notifySpy is a MockEventListener that records every event it's notified
-// about. (*Mocks).processEvent fires notifications from a goroutine without
-// waiting for them, so tests need to synchronize on notified rather than
-// asserting on the event list immediately.
+// about, along with the ack callback it was given. By default it acks
+// immediately (autoAck=true), matching a well-behaved listener; tests
+// exercising the retry path set autoAck=false to simulate a listener that
+// received the notification but hasn't finished yet, and call ackAt
+// explicitly once it "finishes".
 type notifySpy struct {
-	mu       sync.Mutex
-	events   []raw_events.Event
-	notified chan struct{}
+	mu             sync.Mutex
+	events         []raw_events.Event
+	acks           []func(context.Context) error
+	completedCount int // Notify calls that have returned, including any auto-ack
+	autoAck        bool
 }

 func newNotifySpy() *notifySpy {
-	return &notifySpy{notified: make(chan struct{}, 1000)}
+	return &notifySpy{autoAck: true}
 }

-func (s *notifySpy) Notify(_ context.Context, e raw_events.Event) error {
+func (s *notifySpy) Notify(ctx context.Context, e raw_events.Event, ack func(context.Context) error) error {
 	s.mu.Lock()
 	s.events = append(s.events, e)
+	s.acks = append(s.acks, ack)
+	autoAck := s.autoAck
 	s.mu.Unlock()
-	s.notified <- struct{}{}
-	return nil
+
+	var ackErr error
+	if autoAck {
+		ackErr = ack(ctx)
+	}
+
+	s.mu.Lock()
+	s.completedCount++
+	s.mu.Unlock()
+
+	return ackErr
 }

 func (s *notifySpy) eventsSnapshot() []raw_events.Event {
@@ -41,15 +56,43 @@ func (s *notifySpy) eventsSnapshot() []raw_events.Event {
 	return append([]raw_events.Event(nil), s.events...)
 }

+func (s *notifySpy) setAutoAck(v bool) {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	s.autoAck = v
+}
+
+// ackAt manually invokes the i-th recorded ack callback (0-indexed, in
+// Notify call order), simulating the listener finally finishing work it
+// had earlier only been notified about.
+func (s *notifySpy) ackAt(t *testing.T, i int) {
+	t.Helper()
+	s.mu.Lock()
+	ack := s.acks[i]
+	s.mu.Unlock()
+	if err := ack(context.Background()); err != nil {
+		t.Fatalf("ack() error = %v", err)
+	}
+}
+
+// waitForCount blocks until at least n Notify calls have fully completed
+// (including any auto-ack), cumulatively across the test - safe to call
+// more than once with increasing n.
 func (s *notifySpy) waitForCount(t *testing.T, n int, timeout time.Duration) {
 	t.Helper()
-	deadline := time.After(timeout)
-	for i := 0; i < n; i++ {
-		select {
-		case <-s.notified:
-		case <-deadline:
-			t.Fatalf("timed out after %v waiting for notification %d/%d (got %d so far)", timeout, i+1, n, len(s.eventsSnapshot()))
+	deadline := time.Now().Add(timeout)
+	for {
+		s.mu.Lock()
+		got := s.completedCount
+		s.mu.Unlock()
+
+		if got >= n {
+			return
 		}
+		if time.Now().After(deadline) {
+			t.Fatalf("timed out after %v waiting for %d total completed notifications (got %d so far)", timeout, n, got)
+		}
+		time.Sleep(5 * time.Millisecond)
 	}
 }

@@ -87,23 +130,39 @@ func insertRawAmazonEvents(t *testing.T, pool *pgxpool.Pool, shopID string, n in

 func isProcessed(t *testing.T, pool *pgxpool.Pool, shopID, eventID string) bool {
 	t.Helper()
-	var processed, successful bool
+	var processed bool
 	err := pool.QueryRow(context.Background(), `
-		SELECT processed, processed_successfully
+		SELECT processed_at IS NOT NULL
 		FROM mock.shop_amazon_events
 		WHERE shop_id = $1 AND event_id = $2
-	`, shopID, eventID).Scan(&processed, &successful)
+	`, shopID, eventID).Scan(&processed)
 	if err != nil {
 		t.Fatalf("failed to check processed state: %v", err)
 	}
-	return processed && successful
+	return processed
+}
+
+// isNotified reports whether the event has been notified (at least once)
+// but not yet acked/processed.
+func isNotified(t *testing.T, pool *pgxpool.Pool, shopID, eventID string) bool {
+	t.Helper()
+	var notified bool
+	err := pool.QueryRow(context.Background(), `
+		SELECT notified_at IS NOT NULL AND processed_at IS NULL
+		FROM mock.shop_amazon_events
+		WHERE shop_id = $1 AND event_id = $2
+	`, shopID, eventID).Scan(&notified)
+	if err != nil {
+		t.Fatalf("failed to check notified state: %v", err)
+	}
+	return notified
 }

 func countUnprocessed(t *testing.T, pool *pgxpool.Pool, shopID string) int {
 	t.Helper()
 	var n int
 	err := pool.QueryRow(context.Background(), `
-		SELECT count(*) FROM mock.shop_amazon_events WHERE shop_id = $1 AND NOT processed
+		SELECT count(*) FROM mock.shop_amazon_events WHERE shop_id = $1 AND processed_at IS NULL
 	`, shopID).Scan(&n)
 	if err != nil {
 		t.Fatalf("failed to count unprocessed events: %v", err)
@@ -137,11 +196,11 @@ func TestProcessUnprocessedEvents_ProcessesAllEventsAcrossBatches(t *testing.T)
 		t.Fatalf("processUnprocessedEvents() error = %v", err)
 	}

+	spy.waitForCount(t, n, 5*time.Second)
+
 	if got := countUnprocessed(t, pool, shopID); got != 0 {
 		t.Errorf("countUnprocessed() = %d, want 0 (all %d events should be processed across multiple 100-row batches)", got, n)
 	}
-
-	spy.waitForCount(t, n, 5*time.Second)
 }

 func TestProcessUnprocessedEvents_NoListenerConfigured(t *testing.T) {
@@ -158,8 +217,74 @@ func TestProcessUnprocessedEvents_NoListenerConfigured(t *testing.T) {
 		t.Fatalf("processUnprocessedEvents() error = %v", err)
 	}

+	// with no listener, nothing ever acks - the event is expected to stay
+	// "notified" forever, not silently marked processed.
+	if isProcessed(t, pool, shopID, "evt-1") {
+		t.Error("event was marked processed despite no listener being configured to ack it")
+	}
+	if !isNotified(t, pool, shopID, "evt-1") {
+		t.Error("event should be in the notified state after being handed off with no listener to ack it")
+	}
+}
+
+// TestProcessUnprocessedEvents_RetriesUnackedNotification is the core of
+// insight #2's fix: a listener that receives a notification but never acks
+// gets notified again after notifyRetryAfter, and once it does ack (however
+// late), the event settles into processed and stops being retried.
+func TestProcessUnprocessedEvents_RetriesUnackedNotification(t *testing.T) {
+	pool := testdb.Pool(t)
+	spy := newNotifySpy()
+	spy.setAutoAck(false)
+	m := NewMocks(testdb.Logger(), pool).
+		SetListener(spy).
+		WithNotifyRetryAfter(50 * time.Millisecond)
+	ctx := context.Background()
+
+	shopID := "test-shop-" + uuid.NewString()
+	cleanupShop(t, pool, shopID)
+
+	insertRawAmazonEvent(t, pool, shopID, "evt-1")
+
+	if err := m.processUnprocessedEvents(ctx); err != nil {
+		t.Fatalf("processUnprocessedEvents() (1st pass) error = %v", err)
+	}
+	spy.waitForCount(t, 1, 2*time.Second)
+
+	if isProcessed(t, pool, shopID, "evt-1") {
+		t.Fatal("event was marked processed despite the listener never acking")
+	}
+	if !isNotified(t, pool, shopID, "evt-1") {
+		t.Fatal("event should be in the notified state after the first dispatch")
+	}
+
+	// still within notifyRetryAfter: shouldn't be re-notified yet.
+	if err := m.processUnprocessedEvents(ctx); err != nil {
+		t.Fatalf("processUnprocessedEvents() (immediate 2nd pass) error = %v", err)
+	}
+	if got := len(spy.eventsSnapshot()); got != 1 {
+		t.Fatalf("listener was notified %d times before notifyRetryAfter elapsed, want 1", got)
+	}
+
+	time.Sleep(60 * time.Millisecond) // past notifyRetryAfter
+
+	if err := m.processUnprocessedEvents(ctx); err != nil {
+		t.Fatalf("processUnprocessedEvents() (3rd pass, after retry window) error = %v", err)
+	}
+	spy.waitForCount(t, 2, 2*time.Second)
+
+	// the listener "finishes" the first notification late, via the ack it
+	// was originally handed - not a fresh one from the retry.
+	spy.ackAt(t, 0)
+
 	if !isProcessed(t, pool, shopID, "evt-1") {
-		t.Error("event was not marked processed despite no listener being configured")
+		t.Fatal("event should be processed once any recorded ack for it is called")
+	}
+
+	if err := m.processUnprocessedEvents(ctx); err != nil {
+		t.Fatalf("processUnprocessedEvents() (4th pass, after ack) error = %v", err)
+	}
+	if got := len(spy.eventsSnapshot()); got != 2 {
+		t.Fatalf("listener was notified again after being acked: got %d calls, want 2", got)
 	}
 }