Files
inventory-plus-plus/domains/amazon/mock_test.go
T
angelandClaude Sonnet 5 4850bc2d31 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-19 23:20:15 -06:00

375 lines
12 KiB
Go

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 &notifySpy{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(&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 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_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")
}
}