feat: log-tailer offset persistence + in-flight L2 rate-limit accounting (code-review.md § Phase 3)
- logtail: persist the read position (offset + fingerprint of the log's first 512 bytes) in a new logtail_state table (migration 0003) and resume from it on start, so delivery lines written while the panel was down are parsed instead of skipped and their send-log rows no longer stay "queued" forever. Fingerprint mismatch (rotated/recreated while down) reads the file from the start — re-parsing is idempotent; a first-ever start with nothing stored still begins at end-of-file. Writes are throttled to one per 5s, forced on rotation and shutdown. - milter: count messages that passed the level-2 check but have not reached the send log yet (internal/milter/inflight.go), so concurrent SMTP sessions cannot each spend the same last slot. A literal count+insert transaction, as the review suggested, is not possible: the count happens at MAIL FROM and the insert at end-of-message. Reservations are released after the insert, on ABORT, and after a 10-minute TTL — a client that drops mid-transaction must not be able to hold a slot, since the limiter is fail-open by design. Docs: architecture.md (log tailer, persistence, L2 counting), security.md and roadmap.md (restart gap closed, container recreate remains), CHANGELOG, progress.md, code-review.md. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
@@ -20,11 +20,14 @@ import (
|
||||
"codeberg.org/mix/selfpost/internal/store"
|
||||
)
|
||||
|
||||
// StatusStore is the slice of the store the log-tailer needs. *store.Store
|
||||
// satisfies it.
|
||||
// StatusStore is the slice of the store the log-tailer needs: advancing
|
||||
// delivery statuses, pruning the retention window, and remembering how far into
|
||||
// mail.log it has read. *store.Store satisfies it.
|
||||
type StatusStore interface {
|
||||
UpdateStatus(queueID, recipient, status string) (int64, error)
|
||||
DeleteSendLogBefore(cutoff time.Time) (int64, error)
|
||||
LogtailState(path string) (store.LogtailState, bool, error)
|
||||
SaveLogtailState(path string, st store.LogtailState) error
|
||||
}
|
||||
|
||||
// pollInterval is how often the tail loop checks for new bytes / rotation. It
|
||||
@@ -73,12 +76,13 @@ func parseDelivery(line string) (queueID, recipient, status string, ok bool) {
|
||||
}
|
||||
|
||||
// Run follows path and updates send-log statuses until ctx is cancelled, while
|
||||
// a background sweep prunes rows older than retentionDays. It returns nil on a
|
||||
// clean shutdown.
|
||||
// a background sweep prunes rows older than retentionDays. Reading resumes at
|
||||
// the offset the previous run persisted, so a restart parses the delivery lines
|
||||
// written while the panel was down. It returns nil on a clean shutdown.
|
||||
func Run(ctx context.Context, path string, st StatusStore, retentionDays int) error {
|
||||
go retentionLoop(ctx, st, retentionDays)
|
||||
|
||||
return follow(ctx, path, func(line string) {
|
||||
return follow(ctx, path, &tracker{st: st, path: path}, func(line string) {
|
||||
queueID, recipient, status, ok := parseDelivery(line)
|
||||
if !ok {
|
||||
return
|
||||
@@ -166,10 +170,11 @@ func TailLines(path string, n int) ([]string, error) {
|
||||
}
|
||||
|
||||
// follow tails path line by line, calling handle for each complete line, until
|
||||
// ctx is cancelled. It starts at end-of-file (so a restart does not reprocess
|
||||
// history) and reopens the file when it is rotated (inode change from
|
||||
// ctx is cancelled. Where it starts is tr's decision (a persisted offset, the
|
||||
// start of a file that changed while the panel was down, or end-of-file on a
|
||||
// first ever run); it reopens the file when it is rotated (inode change from
|
||||
// logrotate's create, or truncation from copytruncate) so nothing is missed.
|
||||
func follow(ctx context.Context, path string, handle func(string)) error {
|
||||
func follow(ctx context.Context, path string, tr *tracker, handle func(string)) error {
|
||||
var (
|
||||
f *os.File
|
||||
r *bufio.Reader
|
||||
@@ -199,7 +204,7 @@ func follow(ctx context.Context, path string, handle func(string)) error {
|
||||
|
||||
// The container may start before Postfix has created mail.log; wait for it.
|
||||
for {
|
||||
if err := openAt(0, io.SeekEnd); err == nil {
|
||||
if err := openAt(0, io.SeekStart); err == nil {
|
||||
break
|
||||
}
|
||||
select {
|
||||
@@ -208,6 +213,10 @@ func follow(ctx context.Context, path string, handle func(string)) error {
|
||||
case <-time.After(pollInterval):
|
||||
}
|
||||
}
|
||||
if _, err := f.Seek(tr.resume(f), io.SeekStart); err != nil {
|
||||
log.Printf("log-tailer: seek %s: %v", path, err)
|
||||
}
|
||||
r.Reset(f) // the reader buffered from the pre-seek position
|
||||
defer func() {
|
||||
if f != nil {
|
||||
f.Close()
|
||||
@@ -231,11 +240,20 @@ func follow(ctx context.Context, path string, handle func(string)) error {
|
||||
}
|
||||
}
|
||||
|
||||
// read returns how many bytes of the open file have actually been consumed:
|
||||
// the descriptor position less the partial line bufio handed back at EOF,
|
||||
// which is re-read (and completed) on the next drain or the next start.
|
||||
read := func() int64 {
|
||||
pos, _ := f.Seek(0, io.SeekCurrent)
|
||||
return pos - int64(len(pending))
|
||||
}
|
||||
|
||||
ticker := time.NewTicker(pollInterval)
|
||||
defer ticker.Stop()
|
||||
for {
|
||||
select {
|
||||
case <-ctx.Done():
|
||||
tr.record(f, read(), true) // shutdown: the next start resumes here
|
||||
return nil
|
||||
case <-ticker.C:
|
||||
drain()
|
||||
@@ -252,8 +270,12 @@ func follow(ctx context.Context, path string, handle func(string)) error {
|
||||
drain()
|
||||
if err := openAt(0, io.SeekStart); err != nil {
|
||||
log.Printf("log-tailer: reopen %s: %v", path, err)
|
||||
continue
|
||||
}
|
||||
tr.adopt(f)
|
||||
continue
|
||||
}
|
||||
tr.record(f, read(), false)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -4,6 +4,7 @@ import (
|
||||
"context"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"strings"
|
||||
"sync"
|
||||
"testing"
|
||||
"time"
|
||||
@@ -77,10 +78,16 @@ func TestParseDelivery(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// captureStore records UpdateStatus calls for the follow integration test.
|
||||
// captureStore records UpdateStatus calls for the follow integration test and
|
||||
// keeps the persisted read offset in memory, so a "restart" in a test is a
|
||||
// second Run against the same captureStore.
|
||||
type captureStore struct {
|
||||
mu sync.Mutex
|
||||
calls []string
|
||||
|
||||
state store.LogtailState
|
||||
haveState bool
|
||||
stateErr error
|
||||
}
|
||||
|
||||
func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, error) {
|
||||
@@ -92,12 +99,37 @@ func (c *captureStore) UpdateStatus(queueID, recipient, status string) (int64, e
|
||||
|
||||
func (c *captureStore) DeleteSendLogBefore(time.Time) (int64, error) { return 0, nil }
|
||||
|
||||
func (c *captureStore) LogtailState(string) (store.LogtailState, bool, error) {
|
||||
c.mu.Lock()
|
||||
defer c.mu.Unlock()
|
||||
if c.stateErr != nil {
|
||||
return store.LogtailState{}, false, c.stateErr
|
||||
}
|
||||
return c.state, c.haveState, nil
|
||||
}
|
||||
|
||||
func (c *captureStore) SaveLogtailState(_ string, st store.LogtailState) error {
|
||||
c.mu.Lock()
|
||||
defer c.mu.Unlock()
|
||||
if c.stateErr != nil {
|
||||
return c.stateErr
|
||||
}
|
||||
c.state, c.haveState = st, true
|
||||
return nil
|
||||
}
|
||||
|
||||
func (c *captureStore) snapshot() []string {
|
||||
c.mu.Lock()
|
||||
defer c.mu.Unlock()
|
||||
return append([]string(nil), c.calls...)
|
||||
}
|
||||
|
||||
func (c *captureStore) reset() {
|
||||
c.mu.Lock()
|
||||
defer c.mu.Unlock()
|
||||
c.calls = nil
|
||||
}
|
||||
|
||||
// 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.
|
||||
@@ -142,6 +174,80 @@ func TestFollowTailsAndRotates(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// TestFollowResumesAfterRestart covers the persisted read offset: a restart
|
||||
// must parse the delivery lines written while the tailer was down (rows that
|
||||
// would otherwise stay "queued" forever), without re-parsing what it already
|
||||
// read, and must fall back to reading the whole file when the log was rotated
|
||||
// or recreated in the meantime.
|
||||
func TestFollowResumesAfterRestart(t *testing.T) {
|
||||
old := pollInterval
|
||||
pollInterval = 10 * time.Millisecond
|
||||
t.Cleanup(func() { pollInterval = old })
|
||||
|
||||
dir := t.TempDir()
|
||||
path := filepath.Join(dir, "mail.log")
|
||||
// A head longer than fingerprintSize, so the file stays identifiable across
|
||||
// the restart; the lines themselves predate the first start and are ignored.
|
||||
seed := strings.Repeat("host postfix/qmgr[1]: seed line, not a delivery\n", 20)
|
||||
if err := os.WriteFile(path, []byte(seed), 0o644); err != nil {
|
||||
t.Fatalf("seed log: %v", err)
|
||||
}
|
||||
|
||||
cs := &captureStore{}
|
||||
stop := startRun(t, path, cs)
|
||||
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") })
|
||||
stop() // persists the offset past Q1
|
||||
|
||||
// Down: Postfix keeps delivering.
|
||||
appendLine(t, path, "host postfix/smtp[1]: Q2: to=<b@example.net>, dsn=2.0.0, status=sent (ok)")
|
||||
|
||||
cs.reset()
|
||||
stop = startRun(t, path, cs)
|
||||
waitFor(t, func() bool { return contains(cs.snapshot(), "Q2|b@example.net|sent") })
|
||||
if contains(cs.snapshot(), "Q1|a@example.net|sent") {
|
||||
t.Fatal("resumed run re-parsed Q1: offset was not honoured")
|
||||
}
|
||||
stop()
|
||||
|
||||
// Down again, and this time the log is replaced (logrotate + fresh create).
|
||||
// The stored offset belongs to a file that no longer exists, so the new one
|
||||
// must be read from the start.
|
||||
if err := os.WriteFile(path, []byte(strings.Repeat("host postfix/qmgr[1]: fresh log after rotation\n", 20)+
|
||||
"host postfix/smtp[1]: Q3: to=<c@example.net>, dsn=5.1.1, status=bounced (nope)\n"), 0o644); err != nil {
|
||||
t.Fatalf("recreate log: %v", err)
|
||||
}
|
||||
|
||||
cs.reset()
|
||||
stop = startRun(t, path, cs)
|
||||
waitFor(t, func() bool { return contains(cs.snapshot(), "Q3|c@example.net|bounced") })
|
||||
stop()
|
||||
}
|
||||
|
||||
// startRun launches the tailer and returns a function that cancels it and waits
|
||||
// for a clean return, the way a panel restart bookends a run.
|
||||
func startRun(t *testing.T, path string, cs *captureStore) func() {
|
||||
t.Helper()
|
||||
ctx, cancel := context.WithCancel(context.Background())
|
||||
done := make(chan error, 1)
|
||||
go func() { done <- Run(ctx, path, cs, 90) }()
|
||||
// follow() opens and seeks on start; give it a moment before the caller
|
||||
// appends, so the append is not raced by the initial open.
|
||||
time.Sleep(50 * time.Millisecond)
|
||||
return func() {
|
||||
t.Helper()
|
||||
cancel()
|
||||
select {
|
||||
case err := <-done:
|
||||
if err != nil {
|
||||
t.Fatalf("Run: %v", err)
|
||||
}
|
||||
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)
|
||||
|
||||
@@ -0,0 +1,136 @@
|
||||
package logtail
|
||||
|
||||
import (
|
||||
"crypto/sha256"
|
||||
"encoding/hex"
|
||||
"errors"
|
||||
"io"
|
||||
"log"
|
||||
"os"
|
||||
"time"
|
||||
|
||||
"codeberg.org/mix/selfpost/internal/store"
|
||||
)
|
||||
|
||||
const (
|
||||
// fingerprintSize is how many bytes from the head of the log identify it.
|
||||
// Postfix writes a timestamped line per event, so the first 512 bytes are
|
||||
// effectively unique per log generation — enough to tell "the file we were
|
||||
// reading" from "a fresh one created by logrotate while we were down",
|
||||
// which os.SameFile cannot answer across a restart.
|
||||
fingerprintSize = 512
|
||||
// persistInterval throttles the offset write. Losing up to this much
|
||||
// progress on a crash only means re-parsing a few lines (UpdateStatus is
|
||||
// idempotent), which is much cheaper than a database write per poll tick.
|
||||
persistInterval = 5 * time.Second
|
||||
)
|
||||
|
||||
// tracker persists the tailer's read position so a restart resumes where the
|
||||
// previous run stopped instead of jumping to end-of-file — the "send-log rows
|
||||
// stay queued forever" gap (architecture.md § Log tailer). It is used from the
|
||||
// follow loop only, so it needs no locking.
|
||||
type tracker struct {
|
||||
st StatusStore
|
||||
path string
|
||||
|
||||
fp string // fingerprint of the file currently open ("" if too short)
|
||||
saved int64 // last offset written to the store
|
||||
lastSave time.Time
|
||||
}
|
||||
|
||||
// resume returns the byte offset the tailer should start reading f at, having
|
||||
// recorded f's fingerprint for later saves.
|
||||
//
|
||||
// The rules, in order: no stored state at all (first ever start) means start at
|
||||
// the end, so installing the panel does not replay a pre-existing log; a stored
|
||||
// state whose fingerprint still matches means continue from it, parsing the
|
||||
// tail written while the panel was down; anything else means the file is not
|
||||
// the one the offset referred to (rotated, recreated or truncated in the
|
||||
// meantime), so read it from the start. Re-parsing lines already seen is
|
||||
// harmless: UpdateStatus writes the same status onto the same row.
|
||||
func (t *tracker) resume(f *os.File) int64 {
|
||||
size, err := fileSize(f)
|
||||
if err != nil {
|
||||
log.Printf("log-tailer: stat %s: %v (reading from the start)", t.path, err)
|
||||
return 0
|
||||
}
|
||||
t.fp = fingerprintOf(f)
|
||||
|
||||
prev, ok, err := t.st.LogtailState(t.path)
|
||||
if err != nil {
|
||||
log.Printf("log-tailer: read stored offset: %v (starting at end)", err)
|
||||
return size
|
||||
}
|
||||
switch {
|
||||
case !ok:
|
||||
t.saved = size
|
||||
return size
|
||||
case prev.Fingerprint != "" && prev.Fingerprint == t.fp && prev.Offset <= size:
|
||||
t.saved = prev.Offset
|
||||
if prev.Offset < size {
|
||||
log.Printf("log-tailer: resuming %s at offset %d (%d bytes to catch up)",
|
||||
t.path, prev.Offset, size-prev.Offset)
|
||||
}
|
||||
return prev.Offset
|
||||
default:
|
||||
log.Printf("log-tailer: %s changed while the panel was down; reading from the start", t.path)
|
||||
t.saved = 0
|
||||
return 0
|
||||
}
|
||||
}
|
||||
|
||||
// adopt re-fingerprints after the follow loop switched to a rotated-in file and
|
||||
// persists the fresh start immediately, so a restart right after a rotation
|
||||
// does not resume at the old file's offset.
|
||||
func (t *tracker) adopt(f *os.File) {
|
||||
t.fp = fingerprintOf(f)
|
||||
t.saved = -1 // force the write below even if the old offset happened to be 0
|
||||
t.record(f, 0, true)
|
||||
}
|
||||
|
||||
// record persists offset, at most once per persistInterval unless force is set
|
||||
// (rotation and shutdown, where the write must not be skipped).
|
||||
func (t *tracker) record(f *os.File, offset int64, force bool) {
|
||||
if offset == t.saved {
|
||||
return
|
||||
}
|
||||
if !force && time.Since(t.lastSave) < persistInterval {
|
||||
return
|
||||
}
|
||||
if t.fp == "" {
|
||||
// The log was shorter than a fingerprint when we opened it; now that it
|
||||
// has grown, an identifiable one may be available.
|
||||
t.fp = fingerprintOf(f)
|
||||
}
|
||||
if err := t.st.SaveLogtailState(t.path, store.LogtailState{Fingerprint: t.fp, Offset: offset}); err != nil {
|
||||
log.Printf("log-tailer: save offset: %v", err)
|
||||
return
|
||||
}
|
||||
t.saved = offset
|
||||
t.lastSave = time.Now()
|
||||
}
|
||||
|
||||
// fingerprintOf hashes the head of the file. It returns "" for a file too short
|
||||
// to identify — the head would still change as Postfix appends, so such a
|
||||
// fingerprint could not be compared meaningfully on the next start.
|
||||
func fingerprintOf(f *os.File) string {
|
||||
buf := make([]byte, fingerprintSize)
|
||||
n, err := f.ReadAt(buf, 0)
|
||||
if err != nil && !errors.Is(err, io.EOF) {
|
||||
log.Printf("log-tailer: fingerprint read: %v", err)
|
||||
return ""
|
||||
}
|
||||
if n < fingerprintSize {
|
||||
return ""
|
||||
}
|
||||
sum := sha256.Sum256(buf)
|
||||
return hex.EncodeToString(sum[:])
|
||||
}
|
||||
|
||||
func fileSize(f *os.File) (int64, error) {
|
||||
info, err := f.Stat()
|
||||
if err != nil {
|
||||
return 0, err
|
||||
}
|
||||
return info.Size(), nil
|
||||
}
|
||||
Reference in New Issue
Block a user