diff --git a/helm/Chart.yaml b/helm/Chart.yaml index 9799f75f..dd675ecc 100644 --- a/helm/Chart.yaml +++ b/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 diff --git a/internal/lmtp/deliver.go b/internal/lmtp/deliver.go index b165ee21..082a6374 100644 --- a/internal/lmtp/deliver.go +++ b/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(), diff --git a/internal/storage/index/file/folder.go b/internal/storage/index/file/folder.go index 0e346761..26ad8608 100644 --- a/internal/storage/index/file/folder.go +++ b/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