selfpost/internal/store/sendlog_test.go

package store

import (
	"sort"
	"strings"
	"testing"
	"time"
)

// readSendLog returns every send_log row ordered by id. The monitoring UI has
// no equivalent read query, so tests read the table directly.
type sendLogRow struct {
	QueueID  string
	Domain   string
	AppLogin string
	From     string
	To       string
	Subject  string
	Status   string
}

func readSendLog(t *testing.T, s *Store) []sendLogRow {
	t.Helper()
	rows, err := s.db.Query(
		`SELECT queue_id, domain, app_login, from_addr, to_addr, subject, status
		 FROM send_log ORDER BY id`)
	if err != nil {
		t.Fatalf("query send_log: %v", err)
	}
	defer rows.Close()
	var out []sendLogRow
	for rows.Next() {
		var r sendLogRow
		if err := rows.Scan(&r.QueueID, &r.Domain, &r.AppLogin, &r.From, &r.To, &r.Subject, &r.Status); err != nil {
			t.Fatalf("scan: %v", err)
		}
		out = append(out, r)
	}
	return out
}

func TestInsertQueuedAndUpdateStatus(t *testing.T) {
	st := openTestStore(t)

	// Two recipients on the same queue-id → two independent rows (architecture.md
	// § Persistence).
	for _, to := range []string{"a@example.net", "b@example.net"} {
		if err := st.InsertQueued(SendLogEntry{
			QueueID:  "ABC123",
			Domain:   "example.com",
			AppLogin: "app1",
			From:     "noreply@example.com",
			To:       to,
			Subject:  "Hello",
		}); err != nil {
			t.Fatalf("InsertQueued: %v", err)
		}
	}

	rows := readSendLog(t, st)
	if len(rows) != 2 {
		t.Fatalf("want 2 rows, got %d: %+v", len(rows), rows)
	}
	for _, r := range rows {
		if r.Status != StatusQueued {
			t.Fatalf("new row should be queued, got %q", r.Status)
		}
	}

	// One recipient goes to sent; the other stays queued.
	n, err := st.UpdateStatus("ABC123", "a@example.net", StatusSent)
	if err != nil {
		t.Fatalf("UpdateStatus: %v", err)
	}
	if n != 1 {
		t.Fatalf("want 1 row updated, got %d", n)
	}

	rows = readSendLog(t, st)
	if rows[0].Status != StatusSent || rows[1].Status != StatusQueued {
		t.Fatalf("unexpected statuses: %+v", rows)
	}
}

func TestUpdateStatusRecipientCaseInsensitive(t *testing.T) {
	st := openTestStore(t)
	if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "User@Example.NET"}); err != nil {
		t.Fatalf("InsertQueued: %v", err)
	}
	// mail.log may report a differently-cased recipient; matching must still hit.
	n, err := st.UpdateStatus("Q1", "user@example.net", StatusBounced)
	if err != nil {
		t.Fatalf("UpdateStatus: %v", err)
	}
	if n != 1 {
		t.Fatalf("case-insensitive match failed, updated %d rows", n)
	}
}

// The sweep closes only what is still queued, and says it was the sweep: a
// status the log wrote stands, whatever the sweep believed when it listed the
// row.
func TestCloseUnreportedClosesOnlyQueuedRows(t *testing.T) {
	st := openTestStore(t)
	for _, e := range []SendLogEntry{{QueueID: "Q1", To: "Lost@example.net"}, {QueueID: "Q2", To: "done@example.net"}} {
		if err := st.InsertQueued(e); err != nil {
			t.Fatalf("InsertQueued: %v", err)
		}
	}
	if _, err := st.UpdateStatus("Q2", "done@example.net", StatusSent); err != nil {
		t.Fatal(err)
	}

	if n, err := st.CloseUnreported("Q1", "lost@example.net"); err != nil || n != 1 {
		t.Fatalf("CloseUnreported of a queued row = %d, %v; want 1", n, err)
	}
	if n, err := st.CloseUnreported("Q2", "done@example.net"); err != nil || n != 0 {
		t.Fatalf("CloseUnreported of a sent row = %d, %v; want 0", n, err)
	}

	var status, reason string
	for _, c := range []struct{ id, status, reason string }{
		{"Q1", StatusBounced, ReasonReconcile},
		{"Q2", StatusSent, ""},
	} {
		if err := st.db.QueryRow(`SELECT status, reason FROM send_log WHERE queue_id = ?`, c.id).Scan(&status, &reason); err != nil {
			t.Fatal(err)
		}
		if status != c.status || reason != c.reason {
			t.Errorf("%s: status %q reason %q, want %q %q", c.id, status, reason, c.status, c.reason)
		}
	}
}

// A delivery line about a row the sweep closed proves the sweep guessed what
// the log could have said: the log's status wins, the reason goes, and the day
// counts one contradiction - once, however often the line is read again.
func TestUpdateStatusCountsAContradictedSweep(t *testing.T) {
	st := openTestStore(t)
	if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "a@example.net"}); err != nil {
		t.Fatal(err)
	}
	if _, err := st.CloseUnreported("Q1", "a@example.net"); err != nil {
		t.Fatal(err)
	}
	for i := 0; i < 2; i++ {
		if n, err := st.UpdateStatus("Q1", "A@example.net", StatusSent); err != nil || n != 1 {
			t.Fatalf("UpdateStatus = %d, %v", n, err)
		}
	}
	var status, reason string
	if err := st.db.QueryRow(`SELECT status, reason FROM send_log WHERE queue_id = 'Q1'`).Scan(&status, &reason); err != nil {
		t.Fatal(err)
	}
	if status != StatusSent || reason != "" {
		t.Fatalf("status %q reason %q, want sent and no reason", status, reason)
	}
	days, err := st.DeliveryLogDays()
	if err != nil {
		t.Fatal(err)
	}
	if len(days) != 1 || days[0].Contradicted != 1 {
		t.Fatalf("days = %+v, want one day with one contradiction", days)
	}
}

// The reconcile sweep asks for the rows old enough that Postfix should have
// reported on them by now. A message accepted moments ago is simply in flight,
// and one the milter refused never reached the queue at all, so neither is the
// sweep's business.
func TestListQueuedOlderThan(t *testing.T) {
	st := openTestStore(t)

	for _, e := range []SendLogEntry{
		{QueueID: "OLD1", To: "stale@example.net"},
		{QueueID: "NEW1", To: "fresh@example.net"},
	} {
		if err := st.InsertQueued(e); err != nil {
			t.Fatalf("InsertQueued: %v", err)
		}
	}
	// A row the milter refused: no queue-id, and a status the sweep never sees.
	if err := st.InsertRejected(SendLogEntry{To: "refused@example.net"}); err != nil {
		t.Fatalf("InsertRejected: %v", err)
	}
	// A row that has already been delivered, aged the same as the stale one.
	if err := st.InsertQueued(SendLogEntry{QueueID: "DONE1", To: "done@example.net"}); err != nil {
		t.Fatalf("InsertQueued: %v", err)
	}
	if _, err := st.UpdateStatus("DONE1", "done@example.net", StatusSent); err != nil {
		t.Fatalf("UpdateStatus: %v", err)
	}

	cutoff := time.Now().UTC().Add(-2 * time.Minute)
	backdate(t, st, "OLD1", cutoff.Add(-time.Hour))
	backdate(t, st, "DONE1", cutoff.Add(-time.Hour))

	got, err := st.ListQueuedOlderThan(cutoff)
	if err != nil {
		t.Fatalf("ListQueuedOlderThan: %v", err)
	}
	if len(got) != 1 || got[0] != (QueuedDelivery{QueueID: "OLD1", To: "stale@example.net"}) {
		t.Fatalf("got %+v, want only the stale queued row", got)
	}
}

// backdate rewrites a row's acceptance time, so a test can age it past a cutoff
// without waiting.
func backdate(t *testing.T, s *Store, queueID string, at time.Time) {
	t.Helper()
	if _, err := s.db.Exec(
		`UPDATE send_log SET created_at = ? WHERE queue_id = ?`,
		at.UTC().Format(time.RFC3339), queueID,
	); err != nil {
		t.Fatalf("backdate %s: %v", queueID, err)
	}
}

func TestUpdateStatusNoMatch(t *testing.T) {
	st := openTestStore(t)
	if err := st.InsertQueued(SendLogEntry{QueueID: "Q1", To: "a@example.net"}); err != nil {
		t.Fatalf("InsertQueued: %v", err)
	}
	// A queue-id/recipient the milter never recorded must be a no-op, not an error.
	n, err := st.UpdateStatus("Q1", "unknown@example.net", StatusSent)
	if err != nil {
		t.Fatalf("UpdateStatus: %v", err)
	}
	if n != 0 {
		t.Fatalf("want 0 rows updated, got %d", n)
	}
}

// The journal is read by principals who are only entitled to part of it, so
// the scope is part of the query rather than something the caller remembers to
// apply afterwards. A filter that states no scope is a caller that has not
// decided who is asking, and the safe answer to that is nothing.
func TestSendLogScopeIsMandatory(t *testing.T) {
	st := openTestStore(t)
	for _, domain := range []string{"first.example.ru", "second.example.ru"} {
		if err := st.InsertQueued(SendLogEntry{
			QueueID: "Q-" + domain, Domain: domain, AppLogin: "app-" + domain,
			From: "noreply@" + domain, To: "public@example.net", Subject: domain,
		}); err != nil {
			t.Fatalf("InsertQueued: %v", err)
		}
	}

	for name, tc := range map[string]struct {
		filter SendLogFilter
		want   []string
	}{
		"no scope":           {SendLogFilter{}, nil},
		"empty scope":        {SendLogFilter{Domains: []string{}}, nil},
		"all domains":        {SendLogFilter{AllDomains: true}, []string{"first.example.ru", "second.example.ru"}},
		"one domain":         {SendLogFilter{Domains: []string{"first.example.ru"}}, []string{"first.example.ru"}},
		"two domains":        {SendLogFilter{Domains: []string{"first.example.ru", "second.example.ru"}}, []string{"first.example.ru", "second.example.ru"}},
		"unknown domain":     {SendLogFilter{Domains: []string{"third.example.ru"}}, nil},
		"filter within":      {SendLogFilter{Domain: "first.example.ru", Domains: []string{"first.example.ru", "second.example.ru"}}, []string{"first.example.ru"}},
		"filter outside":     {SendLogFilter{Domain: "second.example.ru", Domains: []string{"first.example.ru"}}, nil},
		"app filter outside": {SendLogFilter{AppLogin: "app-second.example.ru", Domains: []string{"first.example.ru"}}, nil},
	} {
		rows, err := st.QuerySendLog(tc.filter, 50, 0)
		if err != nil {
			t.Fatalf("%s: QuerySendLog: %v", name, err)
		}
		var got []string
		for _, r := range rows {
			got = append(got, r.Domain)
		}
		// Which rows came back is the question here; the page's own order is
		// newest-first and is tested where it matters.
		sort.Strings(got)
		if strings.Join(got, ",") != strings.Join(tc.want, ",") {
			t.Errorf("%s: rows for %v, want %v", name, got, tc.want)
		}
		// The count drives pagination, so it has to agree with the page or the
		// UI advertises pages of rows the reader is not allowed to see.
		n, err := st.CountSendLog(tc.filter)
		if err != nil {
			t.Fatalf("%s: CountSendLog: %v", name, err)
		}
		if int(n) != len(tc.want) {
			t.Errorf("%s: count %d, want %d", name, n, len(tc.want))
		}
	}
}

func TestDeleteSendLogBefore(t *testing.T) {
	st := openTestStore(t)

	// Insert one row, then backdate it beyond the retention window by rewriting
	// created_at directly (InsertQueued always stamps "now").
	if err := st.InsertQueued(SendLogEntry{QueueID: "OLD", To: "a@example.net"}); err != nil {
		t.Fatalf("InsertQueued: %v", err)
	}
	old := time.Now().UTC().AddDate(0, 0, -100).Format(time.RFC3339)
	if _, err := st.db.Exec(`UPDATE send_log SET created_at = ? WHERE queue_id = 'OLD'`, old); err != nil {
		t.Fatalf("backdate: %v", err)
	}
	if err := st.InsertQueued(SendLogEntry{QueueID: "NEW", To: "b@example.net"}); err != nil {
		t.Fatalf("InsertQueued: %v", err)
	}

	cutoff := time.Now().UTC().AddDate(0, 0, -90)
	n, err := st.DeleteSendLogBefore(cutoff)
	if err != nil {
		t.Fatalf("DeleteSendLogBefore: %v", err)
	}
	if n != 1 {
		t.Fatalf("want 1 row pruned, got %d", n)
	}
	rows := readSendLog(t, st)
	if len(rows) != 1 || rows[0].QueueID != "NEW" {
		t.Fatalf("retention kept wrong rows: %+v", rows)
	}
}