Files
selfpost/internal/logtail/logtail_test.go
T
mix dc08ccbf7c Phase 6: journal-milter + send-log status tailer + retention
Implement the structured send log (spec 7.3), the project's highest-risk
component since a milter bug can break the relay itself.

- internal/milter: go-milter v0.4.1 journal-milter. Per-connection session
  collects SASL login, From, recipients and Subject across callbacks and
  writes one send_log "queued" row per (queue-id, recipient) at EOM
  (spec 7.3.3). Monitoring only: callbacks return Continue/Accept, recorder
  errors are logged never propagated, so it can never block mail.
- internal/logtail: polling mail.log tailer with rotation handling (inode
  change / truncation), parses sent/deferred/bounced/expired by queue-id +
  recipient and advances rows; background retention sweep prunes rows past
  SEND_LOG_RETENTION_DAYS (default 90) at startup and every 6h.
- internal/store/sendlog.go: InsertQueued, UpdateStatus (case-insensitive
  recipient match), DeleteSendLogBefore + status constants.
- cmd/panel: open the store once and share it across http/milter/tailer;
  replace the journal/logtail stubs with the real roles.
- build/postfix-config.sh: bounded milter timeouts (15/15/30s) so a hung
  milter also fails open in seconds, not the 300s default.

Fix found in-container: SASL login (app_login) was empty because go-milter
keys macros exactly as Postfix sends them, and multi-character macro names
arrive brace-wrapped ({auth_authen}); the SASL-less Phase 0 spike could not
observe this. Added a brace-tolerant macro lookup.

Verified on selfpost.mixfed.ru: gofmt/vet/unit tests green; container e2e
records rows with correct fields and advances status via the tailer; fail-open
confirmed for both an unreachable and a hung milter; retention prunes at start.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
2026-07-13 22:58:34 +03:00

177 lines
5.0 KiB
Go

package logtail
import (
"context"
"os"
"path/filepath"
"sync"
"testing"
"time"
"codeberg.org/mix/selfpost/internal/store"
)
func TestParseDelivery(t *testing.T) {
cases := []struct {
name string
line string
wantOK bool
queueID, recipient, status string
}{
{
name: "sent",
line: "2026-07-11T11:55:34 host postfix/smtp[26]: 41E862C00D9E: to=<a@example.net>, relay=mx.example.net[203.0.113.9]:25, delay=0.5, dsn=2.0.0, status=sent (250 OK)",
wantOK: true,
queueID: "41E862C00D9E",
recipient: "a@example.net",
status: store.StatusSent,
},
{
name: "deferred",
line: "host postfix/smtp[26]: 5900C2C00D9E: to=<y@example.net>, relay=none, delay=30, dsn=4.4.1, status=deferred (connect timed out)",
wantOK: true,
queueID: "5900C2C00D9E",
recipient: "y@example.net",
status: store.StatusDeferred,
},
{
name: "bounced",
line: "host postfix/smtp[26]: ABC: to=<no@example.net>, relay=…, dsn=5.1.1, status=bounced (user unknown)",
wantOK: true,
queueID: "ABC",
recipient: "no@example.net",
status: store.StatusBounced,
},
{
name: "expired maps to bounced",
line: "host postfix/smtp[26]: DEF: to=<slow@example.net>, relay=none, status=expired (delivery temporarily suspended)",
wantOK: true,
queueID: "DEF",
recipient: "slow@example.net",
status: store.StatusBounced,
},
{
name: "qmgr from-line ignored",
line: "host postfix/qmgr[10]: 41E862C00D9E: from=<noreply@example.com>, size=500, nrcpt=1 (queue active)",
wantOK: false,
},
{
name: "smtpd client-line ignored",
line: "host postfix/smtpd[10]: 41E862C00D9E: client=unknown[203.0.113.7]",
wantOK: false,
},
}
for _, c := range cases {
t.Run(c.name, func(t *testing.T) {
q, r, s, ok := parseDelivery(c.line)
if ok != c.wantOK {
t.Fatalf("ok = %v, want %v", ok, c.wantOK)
}
if !ok {
return
}
if q != c.queueID || r != c.recipient || s != c.status {
t.Fatalf("got (%q,%q,%q), want (%q,%q,%q)", q, r, s, c.queueID, c.recipient, c.status)
}
})
}
}
// captureStore records UpdateStatus calls for the follow integration test.
type captureStore struct {
mu sync.Mutex
calls []string
}
func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) {
c.mu.Lock()
defer c.mu.Unlock()
c.calls = append(c.calls, queueID+"|"+recipient+"|"+status)
return 1, nil
}
func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil }
func (c *captureStore) snapshot() []string {
c.mu.Lock()
defer c.mu.Unlock()
return append([]string(nil), c.calls...)
}
// TestFollowTailsAndRotates writes delivery lines to a log file, then rotates
// it (rename + fresh create, as logrotate does) and writes more, asserting the
// tailer picks up lines from both the original and rotated file.
func TestFollowTailsAndRotates(t *testing.T) {
old := pollInterval
pollInterval = 10 * time.Millisecond
t.Cleanup(func() { pollInterval = old })
dir := t.TempDir()
path := filepath.Join(dir, "mail.log")
if err := os.WriteFile(path, []byte("preexisting line, ignored on start\n"), 0o644); err != nil {
t.Fatalf("seed log: %v", err)
}
cs := &captureStore{}
ctx, cancel := context.WithCancel(context.Background())
done := make(chan error, 1)
go func() { done <- Run(ctx, path, cs, 90) }()
// Give follow() time to open at EOF (it seeks to end immediately on start,
// so the seed line above is ignored), then append a delivery line.
time.Sleep(50 * time.Millisecond)
appendLine(t, path, "host postfix/smtp[1]: Q1: to=<a@example.net>, dsn=2.0.0, status=sent (ok)")
waitFor(t, func() bool { return contains(cs.snapshot(), "Q1|a@example.net|sent") })
// Rotate: move the current file aside and create a fresh one (logrotate
// "create"), then append to the new file.
if err := os.Rename(path, path+".1"); err != nil {
t.Fatalf("rotate: %v", err)
}
if err := os.WriteFile(path, nil, 0o644); err != nil {
t.Fatalf("recreate: %v", err)
}
appendLine(t, path, "host postfix/smtp[1]: Q2: to=<b@example.net>, dsn=5.1.1, status=bounced (nope)")
waitFor(t, func() bool { return contains(cs.snapshot(), "Q2|b@example.net|bounced") })
cancel()
select {
case <-done:
case <-time.After(2 * time.Second):
t.Fatal("Run did not return after cancel")
}
}
func appendLine(t *testing.T, path, line string) {
t.Helper()
f, err := os.OpenFile(path, os.O_APPEND|os.O_WRONLY, 0o644)
if err != nil {
t.Fatalf("open for append: %v", err)
}
defer f.Close()
if _, err := f.WriteString(line + "\n"); err != nil {
t.Fatalf("append: %v", err)
}
}
func contains(ss []string, want string) bool {
for _, s := range ss {
if s == want {
return true
}
}
return false
}
func waitFor(t *testing.T, cond func() bool) {
t.Helper()
deadline := time.Now().Add(2 * time.Second)
for time.Now().Before(deadline) {
if cond() {
return
}
time.Sleep(5 * time.Millisecond)
}
t.Fatal("condition not met within timeout")
}