package amazon import ( "context" "sync" "testing" "time" "github.com/google/uuid" "github.com/jackc/pgx/v5/pgxpool" "ruben/inventory2/domains/raw_events" "ruben/inventory2/internal/testdb" ) // notifySpy is a MockEventListener that records every event it's notified // 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 acks []func(context.Context) error completedCount int // Notify calls that have returned, including any auto-ack autoAck bool } func newNotifySpy() *notifySpy { return ¬ifySpy{autoAck: true} } 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() 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 { s.mu.Lock() defer s.mu.Unlock() 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.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) } } // insertRawAmazonEvent inserts directly into mock.raw_shop_events, the same // entry point real mock sale/refund/inventory simulations use. A DB trigger // (mock.process_raw_amazon_event, see migrations 000026/000028) copies the // row into mock.shop_amazon_events and fires pg_notify on // mock_shop_amazon_event_inserted - so this one insert exercises the exact // same path production traffic does, instead of faking the downstream // table directly. func insertRawAmazonEvent(t *testing.T, pool *pgxpool.Pool, shopID, eventID string) { t.Helper() _, err := pool.Exec(context.Background(), ` INSERT INTO mock.raw_shop_events (platform, shop_id, event_timestamp, event_id, raw_payload) VALUES ('amazon', $1, NOW(), $2, '{}'::jsonb) `, shopID, eventID) if err != nil { t.Fatalf("failed to insert raw amazon event: %v", err) } } // insertRawAmazonEvents bulk-inserts n events for shopID in one statement, // each with a distinct event_id/event_timestamp. func insertRawAmazonEvents(t *testing.T, pool *pgxpool.Pool, shopID string, n int) { t.Helper() _, err := pool.Exec(context.Background(), ` INSERT INTO mock.raw_shop_events (platform, shop_id, event_timestamp, event_id, raw_payload) SELECT 'amazon', $1, NOW() + (s || ' milliseconds')::interval, 'evt-' || s, '{}'::jsonb FROM generate_series(1, $2) AS s `, shopID, n) if err != nil { t.Fatalf("failed to insert %d raw amazon events: %v", n, err) } } func isProcessed(t *testing.T, pool *pgxpool.Pool, shopID, eventID string) bool { t.Helper() var processed bool err := pool.QueryRow(context.Background(), ` SELECT processed_at IS NOT NULL FROM mock.shop_amazon_events WHERE shop_id = $1 AND event_id = $2 `, shopID, eventID).Scan(&processed) if err != nil { t.Fatalf("failed to check processed state: %v", err) } 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(¬ified) 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 processed_at IS NULL `, shopID).Scan(&n) if err != nil { t.Fatalf("failed to count unprocessed events: %v", err) } return n } // cleanupShop registers deletion of every row this test's shopID may have // produced, in FK-safe order (shop_amazon_events references raw_shop_events). func cleanupShop(t *testing.T, pool *pgxpool.Pool, shopID string) { t.Cleanup(func() { ctx := context.Background() pool.Exec(ctx, `DELETE FROM mock.shop_amazon_events WHERE shop_id = $1`, shopID) pool.Exec(ctx, `DELETE FROM mock.raw_shop_events WHERE platform = 'amazon' AND shop_id = $1`, shopID) }) } func TestProcessUnprocessedEvents_ProcessesAllEventsAcrossBatches(t *testing.T) { pool := testdb.Pool(t) spy := newNotifySpy() m := NewMocks(testdb.Logger(), pool).SetListener(spy) ctx := context.Background() shopID := "test-shop-" + uuid.NewString() cleanupShop(t, pool, shopID) const n = 150 // exceeds the 100-row LIMIT per batch inside processUnprocessedEvents insertRawAmazonEvents(t, pool, shopID, n) if err := m.processUnprocessedEvents(ctx); err != nil { 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) } } func TestProcessUnprocessedEvents_NoListenerConfigured(t *testing.T) { pool := testdb.Pool(t) m := NewMocks(testdb.Logger(), pool) // no SetListener call 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() 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.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) } } // TestProcessEvents_PollFallbackPicksUpRetryDueEvents proves the poll // branch of ProcessEvents' select actually causes reprocessing, decoupled // from NOTIFY entirely: after the one real insert (which does fire NOTIFY, // same as any other test here), nothing ever triggers another notification // for the rest of the test. The event becomes retry-due almost immediately // (notifyRetryAfter is tiny), so the *only* way it can be dispatched a // second time is the poll timer in the select firing on its own. func TestProcessEvents_PollFallbackPicksUpRetryDueEvents(t *testing.T) { pool := testdb.Pool(t) spy := newNotifySpy() spy.setAutoAck(false) m := NewMocks(testdb.Logger(), pool). SetListener(spy). WithNotifyRetryAfter(30 * time.Millisecond). WithPollInterval(60 * time.Millisecond) shopID := "test-shop-" + uuid.NewString() cleanupShop(t, pool, shopID) ctx, cancel := context.WithCancel(context.Background()) defer cancel() errCh := make(chan error, 1) go func() { errCh <- m.ProcessEvents(ctx) }() select { case <-m.Ready(): case <-time.After(5 * time.Second): t.Fatal("ProcessEvents() did not become ready (LISTEN registered) within 5s") } insertRawAmazonEvent(t, pool, shopID, "evt-1") // first dispatch, via the real NOTIFY. spy.waitForCount(t, 1, 2*time.Second) // second dispatch: nothing will notify again from here on, so this can // only come from the poll branch of the select waking the loop up on // its own and finding the event retry-due. spy.waitForCount(t, 2, 3*time.Second) cancel() select { case err := <-errCh: if err != nil { t.Fatalf("ProcessEvents() returned error = %v after context cancellation, want nil", err) } case <-time.After(5 * time.Second): t.Fatal("ProcessEvents() did not return within 5s of context cancellation") } } // TestProcessEvents_ReactsToNotification drives the actual long-running // loop: LISTEN registration, a real Postgres NOTIFY fired by the DB trigger // on insert, WaitForNotification waking the loop, and the listener callback // - the full stateful path, not just the deterministic batch-processing // core covered above. func TestProcessEvents_ReactsToNotification(t *testing.T) { pool := testdb.Pool(t) spy := newNotifySpy() m := NewMocks(testdb.Logger(), pool).SetListener(spy) shopID := "test-shop-" + uuid.NewString() cleanupShop(t, pool, shopID) ctx, cancel := context.WithCancel(context.Background()) defer cancel() errCh := make(chan error, 1) go func() { errCh <- m.ProcessEvents(ctx) }() select { case <-m.Ready(): case <-time.After(5 * time.Second): t.Fatal("ProcessEvents() did not become ready (LISTEN registered) within 5s") } insertRawAmazonEvent(t, pool, shopID, "evt-1") deadline := time.Now().Add(5 * time.Second) for !isProcessed(t, pool, shopID, "evt-1") { if time.Now().After(deadline) { t.Fatal("event was not processed within 5s of insertion - the reactive LISTEN/NOTIFY wake-up did not fire (the 1-minute poll fallback would eventually catch it, but this test intentionally doesn't wait that long)") } time.Sleep(20 * time.Millisecond) } spy.waitForCount(t, 1, 2*time.Second) if got := spy.eventsSnapshot()[0]; got.StoreID != shopID || got.EventID != "evt-1" { t.Errorf("listener notified with %+v, want StoreID=%q EventID=%q", got, shopID, "evt-1") } cancel() select { case err := <-errCh: if err != nil { t.Fatalf("ProcessEvents() returned error = %v after context cancellation, want nil", err) } case <-time.After(5 * time.Second): t.Fatal("ProcessEvents() did not return within 5s of context cancellation") } } // TestProcessEvents_ShutsDownOnContextCancel checks the lifecycle in // isolation, without depending on NOTIFY timing at all - a fast, low-flake // guard against shutdown regressions (hangs, goroutine leaks) independent // of whether the reactive path above is working. func TestProcessEvents_ShutsDownOnContextCancel(t *testing.T) { pool := testdb.Pool(t) m := NewMocks(testdb.Logger(), pool) ctx, cancel := context.WithCancel(context.Background()) errCh := make(chan error, 1) go func() { errCh <- m.ProcessEvents(ctx) }() select { case <-m.Ready(): case <-time.After(5 * time.Second): t.Fatal("ProcessEvents() did not become ready (LISTEN registered) within 5s") } cancel() select { case err := <-errCh: if err != nil { t.Fatalf("ProcessEvents() returned error = %v after context cancellation, want nil", err) } case <-time.After(5 * time.Second): t.Fatal("ProcessEvents() did not return within 5s of context cancellation") } }