debug: breadcrumbs around LMTP's non-atomic AllocateUID→Save→AppendMessage window

helm/Chart.yaml

@@ -2,8 +2,8 @@ apiVersion: v2
 name: yarilo
 description: Production-grade IMAP/POP3/Submission mail server
 type: application
-version: 2.0.15
-appVersion: "2.1.9"
+version: 2.0.16
+appVersion: "2.1.10"
 keywords:
   - imap
   - submission

internal/lmtp/deliver.go

@@ -8,12 +8,19 @@ import (
 	"log/slog"
 	"strconv"
 	"strings"
+	"sync/atomic"
 	"time"
 
 	"github.com/0kaba0hub/yarilo/pkg/locks"
 	"github.com/0kaba0hub/yarilo/pkg/mailbox"
 )
 
+// deliverCallSeq tags each deliverOne call with a process-local, monotonically
+// increasing id so concurrent deliveries racing on the same folder can be told
+// apart in the shared debug log stream (see the "lmtp: uid allocated" /
+// "lmtp: uid committed" breadcrumbs below).
+var deliverCallSeq atomic.Uint64
+
 // deliverOne saves a single message into the recipient's folder. The
 // caller opens handles via MailboxBackend.OpenUser + IndexBackend.OpenUser
 // (after resolving the recipient's UserInfo) and calls Init() on the
@@ -48,6 +55,15 @@ func deliverOne(box mailbox.UserMailbox, idx mailbox.UserIndex, folder string, r
 	if err != nil {
 		return 0, fmt.Errorf("lmtp: allocate UID: %w", err)
 	}
+	// Breadcrumb for the non-atomic AllocateUID -> Save -> AppendMessage window:
+	// AllocateUID commits and releases the folder lock immediately, so any other
+	// delivery to the same folder can interleave here while this one is still
+	// writing the body (mdbox/sdbox: map lookup + refcount + possible rotation,
+	// measurably slower than maildir's flat-file write). Logged with the uid and
+	// a per-call correlation id so two deliveries racing on the same folder can
+	// be told apart in a shared log stream.
+	callID := deliverCallSeq.Add(1)
+	slog.Debug("lmtp: uid allocated", "user", username, "folder", folder, "uid", uid, "call_id", callID)
 	modseq, err := idx.NextModSeq(f.ID)
 	if err != nil {
 		return 0, fmt.Errorf("lmtp: modseq: %w", err)
@@ -58,6 +74,8 @@ func deliverOne(box mailbox.UserMailbox, idx mailbox.UserIndex, folder string, r
 		return 0, fmt.Errorf("lmtp: save: %w", err)
 	}
 	tIndex := time.Now()
+	slog.Debug("lmtp: body saved, committing index", "user", username, "folder", folder, "uid", uid,
+		"call_id", callID, "filename", filename, "save_ms", tIndex.Sub(tSave).Milliseconds())
 	if err := idx.AppendMessage(f.ID, &mailbox.MessageMeta{
 		UID:          uid,
 		Filename:     filename,
@@ -66,9 +84,12 @@ func deliverOne(box mailbox.UserMailbox, idx mailbox.UserIndex, folder string, r
 		InternalDate: time.Now(),
 		Flags:        flags,
 	}); err != nil {
+		slog.Warn("lmtp: index append failed, rolling back save",
+			"user", username, "folder", folder, "uid", uid, "call_id", callID, "err", err)
 		_ = box.Remove(folder, filename)
 		return 0, fmt.Errorf("lmtp: index append: %w", err)
 	}
+	slog.Debug("lmtp: uid committed", "user", username, "folder", folder, "uid", uid, "call_id", callID)
 	slog.Debug("lmtp: deliver timing",
 		"folder", folder, "size", size,
 		"save_ms", tIndex.Sub(tSave).Milliseconds(),

internal/storage/index/file/folder.go

@@ -566,6 +566,14 @@ func (u *userIndex) SaveFolder(f *mailbox.Folder) error {
 // an external authority (mdbox-style map_uid).
 func (u *userIndex) AppendMessage(folderID uint64, m *mailbox.MessageMeta) error {
 	if err := u.withFolder(folderID, func(fs *folderState) error {
+		// Breadcrumb: the pre-allocated UID (from AllocateUID, called separately
+		// and earlier by the caller — see internal/lmtp/deliver.go) is about to be
+		// committed to the index. next_uid_before lets a log reader spot the exact
+		// symptom of a UID-reuse race: a commit whose UID is < next_uid_before
+		// means something else already advanced the counter past it since
+		// AllocateUID ran, and this commit is landing a stale/reused value.
+		slog.Debug("fileindex: committing pre-allocated uid",
+			"user", u.username, "folder", fs.folder, "uid", m.UID, "next_uid_before", fs.file.Header.NextUID)
 		if err := fs.appendLocked(m); err != nil {
 			return err
 		}
@@ -620,6 +628,11 @@ func (u *userIndex) AllocateUID(folderID uint64) (uint32, error) {
 		}
 		fs.file.Header.NextUID = uid + 1
 		assigned = uid
+		// Pairs with the "fileindex: committing pre-allocated uid" breadcrumb in
+		// AppendMessage — the gap between this log line and that one is exactly
+		// the caller's Save() window (see internal/lmtp/deliver.go), the only
+		// place a concurrent allocation on the same folder could interleave.
+		slog.Debug("fileindex: uid allocated", "user", u.username, "folder", fs.folder, "uid", assigned)
 		return fs.appendMutLog(encU32Update(28, fs.file.Header.NextUID))
 	})
 	return assigned, err